MySQL에서 언제부턴가 아래와 같은 메시지가 콘솔 로그에 눈에 띄기 시작한다. 그 전부터 오류 메시지가 있었는데 확인을 못하고 있었을 수도 있다. 데이터 베이스 동작에는 문제가 되지 않는데 경고 메시지가 계속 눈에 거슬려 수정해 보기로 하고 몇 시간을 투자 한 결과 원인과 해결 방법을 알아 냈다.

Warning: got packets out of order. Expected 10 but received 0
Warning: got packets out of order. Expected 10 but received 7
...

현상 재연

정확한 현상 재연은 아래와 같다.

Nodejs의 mysql2 db connection라이브러리를 활용하며 데이터 베이스 오퍼레이션 후 정확하게 8시간(28,800초)이 지나면 위의 로그 메시지가 출력된다.

좀 더 쉽게 현상을 재연하려면 mysql 의 설정파일인 /etc/mysql/mysql.cnf 에 아래의 속성을 추가 한 후

...
[mysqld] 
wait_timeout = 5 
interactive_timeout = 5

아래의 명령어로 MySQL의 재시작 한다.

$ sudo systemctl restart mysql

변경된 속성의 반영 여부는 아래와 같이 mysql을 접속하여 확인이 가능하다.

$ mysql -u root -p
Enter password: 
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 121
Server version: 8.0.34-0ubuntu0.22.04.1 (Ubuntu)

Copyright (c) 2000, 2023, Oracle and/or its affiliates.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> show variables like '%timeout';
+-----------------------------------+----------+
| Variable_name                     | Value    |
+-----------------------------------+----------+
| connect_timeout                   | 10       |
| delayed_insert_timeout            | 300      |
| have_statement_timeout            | YES      |
| innodb_flush_log_at_timeout       | 1        |
| innodb_lock_wait_timeout          | 50       |
| innodb_rollback_on_timeout        | OFF      |
| interactive_timeout               | 5        |
| lock_wait_timeout                 | 31536000 |
| mysqlx_connect_timeout            | 30       |
| mysqlx_idle_worker_thread_timeout | 60       |
| mysqlx_interactive_timeout        | 28800    |
| mysqlx_port_open_timeout          | 0        |
| mysqlx_read_timeout               | 30       |
| mysqlx_wait_timeout               | 28800    |
| mysqlx_write_timeout              | 60       |
| net_read_timeout                  | 30       |
| net_write_timeout                 | 60       |
| replica_net_timeout               | 60       |
| rpl_stop_replica_timeout          | 31536000 |
| rpl_stop_slave_timeout            | 31536000 |
| slave_net_timeout                 | 60       |
| ssl_session_cache_timeout         | 300      |
| wait_timeout                      | 5        |
+-----------------------------------+----------+
23 rows in set (0.00 sec)

위에서 설정한 속성이 5로 설정된 것으로 확인이 되면 정상적으로 반영된 것이다.(default: 28800)

MySQL을 재시작 후 데이터베이스 오퍼레이션(검색) 후 5초가 지나면 콘솔에 경고메시지가 출력되는 것을 확인할 수 있다.

원인

결론부터 얘기하면 mysql2 드라이버 이슈이며 해당 이슈는 Github mysql2 이슈 트래커에서 확인이 가능하다. 이 글을 작성하는 현재 Bug는 fix됐으나 아직 Main branch로 merge되지는 않은 상태이다. 따라서 mpm으로 mysql2를 다시 설치하더라도 해당 오류를 해결하지 못한다.

From MySQL 8.0.24, an error packet with code 4031 is sent to client before connection is closed. This packet has sequenceId == 0, thus the connection will issue a warning “packets out of order”, which is not correct.

The changes here is just move the block checking & increasing sequence id to go after check for protocol error, since in case of error, we close the connection and return right away.

해석하자면 MySQL 버전 8.0.24부터 connection이 close되기 전에 오류 패킷(코드: 4031, sequenceId: 0)이 클라이언트(node driver)로 전송되며 이로 인해 콘솔로 경고(Warning) 메시지가 출력되고 있었다. 이는 잘못된 동작이며 sequence id를 검사하고 증가시키는 코드 블럭을 프로토콜 오류 검사로직 이후로 옮겼다고 한다.

Fix된 소스코드는 이 곳 소소코드(connecton.js)에서 확인할 수 있다. 410라인부터 확인하면 된다.

해결

로컬에 설치한 mysql2의 소스코드를 아래와 같이 patch하면 된다. 먼저 로컬에 설치된 mysql2의 connection.js를 찾는다. 보통 [app]/node_modules/mysql2/lib 디렉터리에서 확인이 가능하다.

405     /*
406     if (packet) { 
407       if (this.sequenceId !== packet.sequenceId) { 
408         const err = new Error( 
409           `Warning: got packets out of order. Expected ${this.sequenceId} bu    t received ${packet.sequenceId}`
410         ); 
411         err.expected = this.sequenceId; 
412         err.received = packet.sequenceId; 
413         this.emit('warn', err); // REVIEW 
414         // eslint-disable-next-line no-console 
415         console.error(err.message); 
416       } 
417       this._bumpSequenceId(packet.numPackets); 
418     } 
419     */

기존에 있는 코드를 주석처리한 다음 동일 코드를 아래와 같이 프로토콜을 검사하는 로직 뒤로 옮겨 주면 된다.

459     if (packet) { // --> patched by skanto 2023.10.09
460       // Note: when server closes connection due to inactivity, Err packet E    R_CLIENT_INTERACTION_TIMEOUT from MySQL 8.0.24, sequenceId will be 0
461       if (this.sequenceId !== packet.sequenceId) {
462         const err = new Error(
463           `Warning: got packets out of order. Expected ${this.sequenceId} bu    t received ${packet.sequenceId}`
464         );
465         err.expected = this.sequenceId;
466         err.received = packet.sequenceId;
467         this.emit('warn', err); // REVIEW
468         // eslint-disable-next-line no-console
469         console.error(err.message);
470       }
471       this._bumpSequenceId(packet.numPackets);
472     } // <--

이렇게 코드를 수정하고 node 프로그램을 재실행하면 경고 메시지가 더이상 발생되지 않는 것을 확인할 수 있다.

마지막으로, 처음에 설정했던 MySQL 설정 값을 default값으로 되돌려 주고(설정했던 속성을 주석처리) MySQL을 재실행해 주면 된다. 상황종료.