와스킹의 사건현장

개요
 JEUS로그에서 다음과 같은 메시지 발생
[2019.04.07 00:02:06][1] [ms-66] [WEB-3322] Worker (webtob_ms-hth0-7): Reading the request header from Socket[Ip:port, local=47488], sid=2 failed because of java.net.SocketTimeoutException: Read timed out
[2019.04.07 00:02:06][1] [ms-63] [WEB-3322] Worker (webtob_ms-hth0-4): Reading the request header from Socket[ip:port, local=47508], sid=28 failed because of java.net.SocketTimeoutException: Read timed out
[2019.04.07 00:02:06][1] [ms-76] [WEB-3322] Worker (webtob_ms-hth0-17): Reading the request header from Socket[ip:port, local=47530], sid=20 failed because of java.net.SocketTimeoutException: Read timed out

현상 
 DAS에서 MS에 대해 조회시 FAILED라고 뜨는 경우가 발생, USER의 서비스 처리 지연

원인
 WEBTOB에서 JEUS로 연결을 체크하는 부분과 JEUS에서 WEBTOB의 요청을 기다리는 부분에서 상충하여 발생

WEBTOB 설정의  SvrChkTime
*SERVER
ms            SVGNAME = jsvg_ms,            MinProc = 30,  MaxProc = 30, SvrChkTime = 300, Schedule=FA

JEUS 설정의 Read Timeout
DAS WEBADMIN - MS - Engine - WEB Connection - Read Timeout = 120000

여기에 설정된 시간 동안 WebtoB로부터 아무런 메시지가 오지 않는다면 커넥션에 문제가 있다고 간주하고 새로 맺는다.
WebtoB와 JEUS 사이에 방화벽이 있을 경우, WebtoB가 보내는 Ping 메시지 도착 여부를 이 설정으로 체크할 수 있다.

따라서 WEBTOB에서 JEUS로 연결을 체크하는 주기는 300초 이지만, JEUS에서는 120초가 지나면 연결을 끊도록 되어 있었기 때문에 발생한 문제

해결방안

 WEBTOB 설정의 SvrChkTime보다 JEUS 설정의 Read Timeout이 크도록 설정
 JEUS 설정의 Read Timeout을 500초로 지정하여 해결

 

 
WEBTOB 큐잉 중인 요청 건 인데 클라이언트 연결을 끊으면 어떻게 되는지??

 1) 연결 끊김 인지되서 큐잉에서 제거 or JEUS 로 전달하지 않음
  -> cqcnt가 증가하는 큐잉인 상태인 경우
    cqcnt에서 대기 중인 클라이언트가 연결을 끊으면 webtob에서 큐잉 제거 및 JEUS로 해당 연결을 전달하지 않습니다.

  log keyword
   jsv: Premature client close
 
 2) 일단 JEUS 전달까지 되어 로직도 다 수행되고 완료 후 클라이언트로 응답 줄 때 끊김 인지하여 에러로그 발생
  -> cqcnt가 아닌 정상적인 Thread 요청에 대해 Client가 응답을 받기 전 연결을 끊으면 응답 시 끊김에 대한 인지와 함께 에러로그 발생합니다.

  log keyword
   Client has closed connection. Discard response message

현상
 외부 클라이언트에서 접속하지 못하는 현상 발생

원인
 1) wsadmin 의 st -p 로 html 프로세스 상태 확인
 html 프로세스의 status가 BRUN 상태로 남는 것을 확인

   -------------------------------------------------------------------------
   svr_name   svgname     spr_no(pid)  status    count    avg(rt)  clid svc 
   -------------------------------------------------------------------------

   html       htmlg        37(544822)   RDY     29235   0.0271( 0)   -1 -

   html       htmlg        38(630880)  BRUN     25869   0.0472(351) 5180 swf

   html       htmlg        39(606336)   RDY     29042   0.0290( 0)   -1 -

   html       htmlg        40(512038)   RDY     28183   0.0384( 0)   -1 -

   html       htmlg        41(503842)   RDY     27471   0.0445( 0)   -1 -

   html       htmlg        42(491548)   RDY     27667   0.0408( 0)   -1 -

 

 2) wsadmin 의 ci 로 클라이언트 상태 확인
 st -p 에서 보았던 BRUN상태의 clientID와 매칭 되는 부분과 접속이 BRUN상태라는 것을 확인할 수 있으며, 실질적으로 외부 사용자는 server쪽으로 요청을 했지만 계속 기다리는 상황인 것으로 추정.

------------------------------------------------------------------------
 no   status count idle    local_ipaddr:port    remote_ipaddr:port  spri
------------------------------------------------------------------------
 5178    RDY     2   33     172.17.1.72:80    221.166.124.147:3097    -1      

 5179    RDY     2   33     172.17.1.72:80    221.166.124.147:3099    -1      

 5180    RUN     4  190     172.17.1.72:80     218.150.29.223:1122    38      

 5181    RDY     2   30     172.17.1.72:80    221.166.124.147:3100    -1      

 5182    RDY     2   33     172.17.1.72:80    221.166.124.147:3098    -1      

 5183    RDY     2   33     172.17.1.72:80    221.166.124.147:3102    -1      

 

 3) network상태 확인
 netstat -an | grep [clientIP] 로 네트워크 상태 확인, sendQ의 byte size가 줄어들지 않고 계속 유지되고 있는 것 확인
 Client와 연결된 hth 프로세스가 더 이상 sendQ에 write를 못하고 대기하고 있는 상태로 추정

# netstat -na|grep 218.150.29.223

Active Internet connections (including servers)
Proto Recv-Q Send-Q  Local Address          Foreign Address        (state)

tcp4       0 119826  172.17.1.72.80         218.150.29.223.1122    ESTABLISHED

# netstat -na|grep 218.150.29.223

Active Internet connections (including servers)
Proto Recv-Q Send-Q  Local Address          Foreign Address        (state)

tcp4       0 119826  172.17.1.72.80         218.150.29.223.1122    ESTABLISHED

# netstat -na|grep 218.150.29.223

Active Internet connections (including servers)
Proto Recv-Q Send-Q  Local Address          Foreign Address        (state)

tcp4       0 119826  172.17.1.72.80         218.150.29.223.1122    ESTABLISHED

# netstat -na|grep 218.150.29.223

Active Internet connections (including servers)
Proto Recv-Q Send-Q  Local Address          Foreign Address        (state)

tcp4       0 119826  172.17.1.72.80         218.150.29.223.1122    FIN_WAIT_1

 

해결방안
 네트워크 상태 확인 필요, BRUN을 유발하는 거래 차단

개요
 Network의 문제로 기인한 Web 서비스 지연 및 불가 상황

현상
 Web 화면 호출이 전혀 되지 않고, 단순 image파일 개별 호출도 되지 않는 현상 발생.
 WebtoB/JEUS 재 기동 후에는 서비스 정상 작동함.

원인
 1) wsadmin을 통한 확인(wsadmin : st -s, si)
    html서비스의 평균 처리시간이 오래 걸렸으며(60초이상), Queueing 또한 발생.
    이 상황으로 인해 단순한 image파일도 호출되지 않았음.
 

 2) WebtoB의 error log 확인 결과
    [27/Mar/2018:08:43:45 +0900] [error] [client -] TIMEOUT is expired while svc is running
   [27/Mar/2018:08:43:49 +0900] [error] [client -] TIMEOUT is expired while svc is running
   위 로그에서 확인되는 사항은 사용자의 요청이 WebtoB의 TIMEOUT(300초)시간을 지났다는 로그임.
   WebtoB의 TIMEOUT은 Client와 WebtoB사이의 데이터 전송 중 TIMOUT시간 (300초) 이상 어떠한 패킷(데이터)도 Client와 WebtoB사이에 전송되지 않았을 경우 적용되는 값임.
    Network Bottleneck이나 기타 요인으로 인해 패킷 전송지연이 발생되었을 것으로 판단됨.

해결방안
 본 상황은 큰 파일을 동시에 많은 사용자가 다운 받음으로 인해 발생된 서비스 지연에 해당한다.
 즉 시스템적인 오류가 아닌 업무적인 특성으로 인해 과부하가 발생한 것으로, Network 전송속도를 개선하는 것이 근본적인 해결방법임.

 

개요
 WebtoB Vhost에 URLREWRITE 설정 후 503에러 발생
 Rewrite 설정시 하위 Extension 붙은 거래에 대하여 처리 불가문제 발생


현상
 rewrite 할 도메인에 대하여 rewrite로 전달 해주는 VHOST를 추가하고, 해당 VHOST를 SVGROUP에 포함시키지 않은 환경 설정으로 인해 하위 URI(Extension) 붙은 거래가 node로 빠져서 처리 불가.
 ※ 단. 하위 URI없는 순수 URL은 리라이팅 정상 처리
ex) http://www.abc.com => https://www.abc.com (o)
    http://www.abc.com/test.jsp => http://www.abc.com/test.jsp (x)

원인
 1) 환경파일 분석

  80포트를 사용하는 vh_def_abc 를 추가하고 해당 vhost로 유입 시 443포트로 URLREWRITE 적용

*VHOST
vh_def_abc                DOCROOT="해당 DOCROOT",
                          PORT=80,
                          HOSTNAME="서비스IP",
                          HostAlias="www.abc.com",
                          URLRewrite=Y,
                          URLRewriteConfig="config/rewrite_abc.cfg"
        
vh_abc                   DOCROOT="해당 DOCROOT",
                          PORT=443,
                          HOSTNAME="서비스IP",
                          HostAlias="www.abc.com",

*SVRGROUP
 htmlg          SVRTYPE=HTML

jsvg_abc     SVRTYPE=JSV, VHOSTNAME="vh_abc"
 
*SERVER
html   SVGNAME=htmlg, MinProc=300, MaxProc=600, Schedule=FA
abc    SVGNAME=jsvg_abc, MinProc=60, MaxProc=600, SvrChkTime=300, Schedule=FA
  
 2) vhost와 JEUS와의 연관 관계

  위 반영된 설정 대로 trace확인 결과 유입된 URI를 분석 후 Vhost와 맵핑되어 있는 JSV Server절을 찾으나, Vhost(vh_def_abc) 맵핑되어 있는 SVRGROUP을 찾을 수 없어 에러를 도출 합니다.

아래는 재현 시  HTH Trace 입니다.

[2018/02/02:15:37:51] HTH-1020 T http_parse.c:362 0: reqline(21)="GET /get.jsp HTTP/1.1"
[2018/02/02:15:37:51] HTH-1020 T http_parse.c:500 0: uripath after unescape[8]="/get.jsp"
[2018/02/02:15:37:51] HTH-1020 T http_io.c:198 0: cli_rdata_getline(45)="Accept: text/html, application/xhtml+xml, */*"
[2018/02/02:15:37:51] HTH-1020 T http_parse.c:819 0: parse_mime_hdr: key(6)="Accept", val(37)="text/html, application/xhtml+xml, */*"
--------------------------------------------------------(중략)--------------------------------------------------------
[2018/02/02:15:37:51] HTH-1020 T http_util.c:2202 make_errmsg("Request (%s) arrived at vhost (%s) is routed to server (%s). But, the server's vhost is different. svc=%s. Check WebtoB configuration.", ...): "Request (GET /get.jsp HTTP/1.1) arrived at vhost (vh_def_abc) is routed to server (abc). But, the server's vhost is different. svc=abc. Check WebtoB configuration."
[2018/02/02:15:37:51] HTH-1020 T http_msg.c:2038 0: send_http_error: svrtype=16, errmsg=Request (GET /get.jsp HTTP/1.1) arrived at vhost (vh_def_abc) is routed to server (abc). But, the server's vhost is different. svc=abc. Check WebtoB configuration.

 ==> Vhost와 연관된 server절을 찾을 수 없어 errmsg를 생성

[2018/02/02:15:37:51] HTH-1020 T main_hth.c:878 0: msg to tproc: msgtype=142, svcname=, len=222
[2018/02/02:15:37:51] HTH-1020 T http_io.c:2680 free--3() hp=6000000003210c70
[2018/02/02:15:37:51] HTH-1020 T http_error.c:358 _make_http_error_msg: requested_url=/get.jsp
[2018/02/02:15:37:51] HTH-1020 T http_util.c:1814 _wb_make_content_type(0000000000000000"(null)", 6000000000008ec0"text/html", 0, -1, -1):
[2018/02/02:15:37:51] HTH-1020 T http_util.c:1839 _wb_make_content_type--1: default_charset = "Off"
[2018/02/02:15:37:51] HTH-1020 T http_etc.c:2922 headers_response. svri=1, vhosti=0, hpp=9ffffffffffff050(6000000003217910)
[2018/02/02:15:37:51] HTH-1020 T http_etc.c:2974 headers_response. hpp=9ffffffffffff050(6000000003217910)
[2018/02/02:15:37:51] HTH-1020 T main_hth.c:1876 0: reply_to_client--1: fd=12, status=1, whp=6000000003217910, flags=0x20
[2018/02/02:15:37:51] HTH-1020 T main_hth.c:1908 0: msg to client: ind=0, msgtype=2301, svci=0, len=342, clen=192
[2018/02/02:15:37:51] HTH-1020 T http_io.c:1744 0: write_to_cli_async(60000000005e4060): whp=6000000003217910, 0(342)/342
[2018/02/02:15:37:51] HTH-1020 T http_io.c:1786 0: write_to_cli_async--1: write(12, 6000000003217970, 342)=342: errno=0
[2018/02/02:15:37:51] HTH-1020 T http_io.c:2783 0: accesslog_and_init_status: clii=0, rhp=0000000000000000, saved_rhp=60000000032a00c0, msgtype=2301, svrtype=16
[2018/02/02:15:37:51] HTH-1020 T http_log.c:897 process_log: logind=1, len=76, data="16.16.16.8 - - [02/Feb/2018:15:37:51 +0900] "GET /get.jsp HTTP/1.1" 503 192

 ==> 에러 메세지 발생 후 503에러 도출

 3) 결론
  WEBTOB에서 Rewritng Rule을 적용하기 이전에 vhost -> svrgroup -> sever 의 관계를 먼저 파악한 뒤 Rewritng Rule이 적용됨.

해결방안
 Rewritng Rule을 쓰기 위해서는 Vhost와 SERVER과의 구조(vhost -> svrgroup -> sever)가 필수적으로 구성이 되어야 함.

 문제의 환경파일을 아래와 같이 구성하여 Vhost와 SERVER과의 구조를 필수적으로 구성하여야 함.

*VHOST
vh_def_abc                DOCROOT="해당 DOCROOT",
                          PORT=80,
                          HOSTNAME="서비스IP",
                          HostAlias="www.abc.com",
                          URLRewrite=Y,
                          URLRewriteConfig="config/rewrite_abc.cfg"
        
vh_abc                   DOCROOT="해당 DOCROOT",
                          PORT=443,
                          HOSTNAME="서비스IP",
                          HostAlias="www.abc.com"

*SVRGROUP
htmlg          SVRTYPE=HTML
jsvg_abc       SVRTYPE=JSV, VHOSTNAME="vh_abc, vh_def_abc"
 
*SERVER
html   SVGNAME=htmlg, MinProc=300, MaxProc=600, Schedule=FA
abc    SVGNAME=jsvg_card, MinProc=60, MaxProc=600, SvrChkTime=300, Schedule=FA

 

개요
 WEBTOB를 기동하였으나, Port LISTEN이 되지 않음.
 WEBTOB의 IPCPerm 설정이 되지 않고, htl을 root로 설정하게 되어, 기동 시 htld의 퍼미션 거부로 인한 Port의 LISTEN이 되지 않음.

현상
 다음과 같은 로그가 발생하며 WEBTOB내 지정된 Port들이 LISTEN 하지 않음

[2018/11/04:05:47:49] HTH-12518 W HTH0072: Failed to connect to HTL. fail count=1, path=jeus/webserver/path/htld  errno=13(Permission denied)
[2018/11/04:05:47:51] HTH-12518 W HTH0072: Failed to connect to HTL. fail count=2, path=jeus/webserver/path/htld  errno=13(Permission denied)

 주의하여야 할 점은 이렇게 htld가 Permission denied를 당했음에도 불구하고, 프로세스를 검색하면 htl 프로세스가 보이며, 심지어 wsadmin에서 server 상태조회를 해보면 정상으로 보인다.!
 생각해보면.. 받아주는 포트가 막혀있는 상황일 뿐이지.. server는 멀쩡했을 것이다...
 아무튼 syslog를 자세히 들여다 보지 않는 이상 발견하기 굉장히 모호한 현상이다.

(wsadm) [2018/11/04:05:49:20]: si

------------------------------------------------------------------------------------------
 hth   svrname (svri)   status      reqs     count cqcnt    aqcnt qpcnt emcnt rscnt rbcnt
------------------------------------------------------------------------------------------
   0  html       (  0)   RDY           0         0     0        0     0     0     0     0
   0  fep        (  1)   RDY           0         0     0        0     0     0     0     0

원인
 왜 htld가 Permission denied를 당했는지 추적을 해보았다.

[jeus/webserver/path]ll
total 6
srwx------   1 jeus       tmax             0 Nov  5 10:00 hthd000
srwx------   1 root       tmax             0 Nov  5 10:00 htld
-rw-------   1 jeus       tmax          1536 Nov  5 10:00 webtob.pid
srwx------   1 jeus       tmax             0 Nov  5 10:00 wsmd

 그렇다면 htld는 왜 Permission이 저렇게 되어 있는 것인가?
 webtob 설정에서 정답을 찾을 수 있었다.
 $WEBTOB_HOME/config/http.m의 IPCPerm 이라는 설정을 보자

IPCPerm                                                                                     
● 종류: Numeric                                                                             
● 범위: 0600 ~ 0700                                                                         
● 기본값: 0700                                                                              
● WebtoB 내부 프로세스(WSM, HTL, HTH, HTMLS, CGIS 등) 및 관리 프로세스(wsadmin) 간의 내부 통신(IPC)에 사용하는 named-pipe의 접근권한을 설정한다.                                         
참고                                                                                         
UNIX/Linux 환경에서만 사용할 수 있다.                                                       

 그렇다. IPCPerm을 지정하지 않아, 기본값이 적용되었던 것이다.


해결방안
 $WEBTOB_HOME/config/http.m의 IPCPerm을 다음과 같이 설정하자.

*NODE
IPCPERM = 0777,

 ※참고사항
 WEBTOB에서 1024 이하의 Port를 사용하려면 System계정인 root의 권한이 필요하다.
 따라서 $WEBTOB_HOME/bin/htl의 권한에 setuid를 부여 해주어야 한다.