node.js로 웹서비스 만들기 (24. 서버 다운 문제 대응)

서버를 올려놓고 서버가 잘 동작하나 확인해보니 뜬금없이 서버가 최소 하루에 한번은 다운되는 문제가 발생했습니다.

 

엥!!! 이게 뭐지... @_@

 

서버 다운 에러 원인 파악

아래 명령어로 로그 출력해 원인을 파악해보니...

$ sudo journalctl -u google-startup-scripts.service

…

-- Reboot --
Jul 05 08:40:46 newquiz-instance-1 systemd[1]: Starting Google Compute Engine Startup Scripts...
Jul 05 08:40:46 newquiz-instance-1 google_metadata_script_runner[930]: Starting startup scripts (version 20230>
Jul 05 08:40:46 newquiz-instance-1 google_metadata_script_runner[930]: Found startup-script in metadata.
Jul 05 08:40:48 newquiz-instance-1 google_metadata_script_runner[930]: startup-script:
Jul 05 08:40:48 newquiz-instance-1 google_metadata_script_runner[930]: startup-script: > newquiz@1.0.0 dev /ho>
Jul 05 08:40:48 newquiz-instance-1 google_metadata_script_runner[930]: startup-script: > nodemon index.js
Jul 05 08:40:49 newquiz-instance-1 google_metadata_script_runner[930]: startup-script: [nodemon] watching extensions: js,mjs,json
Jul 05 08:40:49 newquiz-instance-1 google_metadata_script_runner[930]: startup-script: [nodemon] starting `node index.js`
Jul 05 08:40:50 newquiz-instance-1 google_metadata_script_runner[930]: startup-script: google authentication installed at /home/als2019/project/newQuiz/secure/mygcpfirstsample-8>
Jul 05 08:40:50 newquiz-instance-1 google_metadata_script_runner[930]: startup-script: google cloud storage bucket name is  newquiz_stg
Jul 05 08:40:50 newquiz-instance-1 google_metadata_script_runner[930]: startup-script: 3000에서 서버실행중.
Jul 05 08:40:50 newquiz-instance-1 google_metadata_script_runner[930]: startup-script: mysql 연결 성공
Jul 05 10:45:02 newquiz-instance-1 google_metadata_script_runner[930]: startup-script: [GET] root
Jul 05 16:40:50 newquiz-instance-1 google_metadata_script_runner[930]: startup-script: events.js:174
Jul 05 16:40:50 newquiz-instance-1 google_metadata_script_runner[930]: startup-script:       throw er; // Unhandled 'error' event
Jul 05 16:40:50 newquiz-instance-1 google_metadata_script_runner[930]: startup-script:       ^
Jul 05 16:40:50 newquiz-instance-1 google_metadata_script_runner[930]: startup-script:
Jul 05 16:40:50 newquiz-instance-1 google_metadata_script_runner[930]: startup-script: Error: Packets out of order. Got: 0 Expected: 3
Jul 05 16:40:50 newquiz-instance-1 google_metadata_script_runner[930]: startup-script:     at Parser._tryReadPacketHeader (/home/als2019/project/newQuiz/node_modules/mysql/lib/p>
Jul 05 16:40:50 newquiz-instance-1 google_metadata_script_runner[930]: startup-script:     at Parser.write (/home/als2019/project/newQuiz/node_modules/mysql/lib/protocol/Parser.>
Jul 05 16:40:50 newquiz-instance-1 google_metadata_script_runner[930]: startup-script:     at Protocol.write (/home/als2019/project/newQuiz/node_modules/mysql/lib/protocol/Proto>
Jul 05 16:40:50 newquiz-instance-1 google_metadata_script_runner[930]: startup-script:     at Socket.<anonymous> (/home/als2019/project/newQuiz/node_modules/mysql/lib/Connection>
Jul 05 16:40:50 newquiz-instance-1 google_metadata_script_runner[930]: startup-script:     at Socket.<anonymous> (/home/als2019/project/newQuiz/node_modules/mysql/lib/Connection>
Jul 05 16:40:50 newquiz-instance-1 google_metadata_script_runner[930]: startup-script:     at Socket.emit (events.js:198:13)
Jul 05 16:40:50 newquiz-instance-1 google_metadata_script_runner[930]: startup-script:     at addChunk (_stream_readable.js:288:12)
Jul 05 16:40:50 newquiz-instance-1 google_metadata_script_runner[930]: startup-script:     at readableAddChunk (_stream_readable.js:269:11)
Jul 05 16:40:50 newquiz-instance-1 google_metadata_script_runner[930]: startup-script:     at Socket.Readable.push (_stream_readable.js:224:10)
Jul 05 16:40:50 newquiz-instance-1 google_metadata_script_runner[930]: startup-script:     at TCP.onStreamRead [as onread] (internal/stream_base_commons.js:94:17)
Jul 05 16:40:50 newquiz-instance-1 google_metadata_script_runner[930]: startup-script: Emitted 'error' event at:
Jul 05 16:40:50 newquiz-instance-1 google_metadata_script_runner[930]: startup-script:     at Connection._handleProtocolError (/home/als2019/project/newQuiz/node_modules/mysql/l>
Jul 05 16:40:50 newquiz-instance-1 google_metadata_script_runner[930]: startup-script:     at Protocol.emit (events.js:198:13)
Jul 05 16:40:50 newquiz-instance-1 google_metadata_script_runner[930]: startup-script:     at Protocol._delegateError (/home/als2019/project/newQuiz/node_modules/mysql/lib/proto>
Jul 05 16:40:50 newquiz-instance-1 google_metadata_script_runner[930]: startup-script:     at Protocol.handleParserError (/home/als2019/project/newQuiz/node_modules/mysql/lib/pr>
Jul 05 16:40:50 newquiz-instance-1 google_metadata_script_runner[930]: startup-script:     at Parser._tryReadPacketHeader (/home/als2019/project/newQuiz/node_modules/mysql/lib/p>
Jul 05 16:40:50 newquiz-instance-1 google_metadata_script_runner[930]: startup-script:     at Parser.write (/home/als2019/project/newQuiz/node_modules/mysql/lib/protocol/Parser.>
Jul 05 16:40:50 newquiz-instance-1 google_metadata_script_runner[930]: startup-script:     [... lines matching original stack trace ...]
Jul 05 16:40:50 newquiz-instance-1 google_metadata_script_runner[930]: startup-script:     at Socket.emit (events.js:198:13)
Jul 05 16:40:50 newquiz-instance-1 google_metadata_script_runner[930]: startup-script: [nodemon] app crashed - waiting for file changes before starting...

 

출력된 로그를 분석해보니 sql 서버에 접속하는 과정에 무언가 문제가 발생한 것으로 보여지고

Error: Packets out of order. Got: 0 Expected: 3
at Parser._tryReadPacketHeader (/home/als2019/project/newQuiz/node_modules/mysql/lib/p>

서버가 실행되고 8시간 후에 문제가 발생한 것을 확인할 수 있었습니다.

Jul 05 10:45:02 newquiz-instance-1 google_metadata_script_runner[930]: startup-script: [GET] root
Jul 05 16:40:50 newquiz-instance-1 google_metadata_script_runner[930]: startup-script: events.js:174

여기저기 구글링 해서 확인해보니 이문제는 mysql의 기본 wait_timeout 설정이 8시간으로 되어 있어 발생한 문제로 보였습니다.

 

가만히 생각해보니 얼마 전 Compute engine 일정 관리를 사용해 오전 8시 40분쯤 VM 인스턴스가 동작하게 해놨었네...

시간도 8시간으로 딱맞고 범인을 찾았습니다.

 

그래도 정확한 확인을 위해 Cloud shell을 사용해 sql 인스턴스에 접속해 아래 명령어로 timeout 관련된 설정을 확인해보았습니다.

“wait_timeout 28800 -> 8시간” 범인 맞음.

 

서버 다운 에러 수정 (대기 시간 변경)

wait_timeout 시간을 늘려 문제를 해결하기로 하고 

SQL > DB 인스턴스를 선택 후 상단 “수정” 버튼을 클릭합니다.

수정 화면에서 쭉 스크롤을 내려서 “플래그” 항목을 펼침한 상태로 아래와 같이 wait_timeout을 최대 값으로 입력하고 ”저장” 버튼을 클릭합니다.

 

마무리

이렇게 수정한 후, 며칠동안 지켜보니 서버가 다운되는 문제가 더이상 발생하지 않아 해당 문제가 해결 되었음을 확인할 수 있었습니다.