mysqld got signal 6 error / DB 재시작 에러 해결 1

고도화 프로젝트 후 SI는 철수하고..

 

한달쯤 지났을까?

 

제일 보고 싶지않은 에러가 떴다.

mysqld got signal 6

DB 재시작이슈가 발생했다

 

에러로그를 확인해보니

 

2023-01-04 16:14:27 0x7f76a70d3700  InnoDB: Assertion failure in thread 140147585529600 in file trx0trx.ic line 213
InnoDB: Failing assertion: !trx->has_search_latch
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: http://dev.mysql.com/doc/refman/5.7/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
07:14:27 UTC - mysqld got signal 6 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
Attempting to collect some information that could help diagnose the problem.
As this is a crash and something is definitely wrong, the information
collection process might fail.

key_buffer_size=33554432
read_buffer_size=2097152
max_used_connections=154
max_threads=1000
thread_count=128
connection_count=128
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 10286111 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x7f73bc69cf00
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 7f76a70d2e28 thread_stack 0x30000
/data/bin/mysqld(my_print_stacktrace+0x35)[0xf45e05]
/data/bin/mysqld(handle_fatal_signal+0x4a4)[0x7cd464]
/lib64/libpthread.so.0[0x316c40f7e0]
/lib64/libc.so.6(gsignal+0x35)[0x316c0324f5]
/lib64/libc.so.6(abort+0x175)[0x316c033cd5]
/data/bin/mysqld(_Z18ut_print_timestampP8_IO_FILE+0x0)[0x7bc9ce]
/data/bin/mysqld[0x1045499]
/data/bin/mysqld(_Z18close_thread_tableP3THDPP5TABLE+0x288)[0xcc1468]
/data/bin/mysqld(_Z19close_thread_tablesP3THD+0x31b)[0xcc1e6b]
/data/bin/mysqld(_ZN18Prepared_statement7prepareEPKcm+0x728)[0xd3e2f8]
/data/bin/mysqld(_Z19mysqld_stmt_prepareP3THDPKcj+0x106)[0xd3f226]
/data/bin/mysqld(_Z16dispatch_commandP3THDPK8COM_DATA19enum_server_command+0xb1d)[0xd18dcd]
/data/bin/mysqld(_Z10do_commandP3THD+0x194)[0xd1a324]
/data/bin/mysqld(handle_connection+0x29c)[0xdea0fc]
/data/bin/mysqld(pfs_spawn_thread+0x174)[0xfbdbf4]
/lib64/libpthread.so.0[0x316c407aa1]
/lib64/libc.so.6(clone+0x6d)[0x316c0e8c4d]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (7f73bdc4fb10):  SELECT DISTINCT        CC.*        ,
Connection ID (thread ID): 2486689
Status: NOT_KILLED

The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
information that should help you find out what is causing the crash.
2023-01-04T07:14:27.827525Z mysqld_safe Number of processes running now: 0
2023-01-04T07:14:27.830702Z mysqld_safe mysqld restarted
2023-01-04T16:14:28.009437+09:00 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2023-01-04T16:14:28.009545+09:00 0 [Note] --secure-file-priv is set to NULL. Operations related to importing and exporting data are disabled
2023-01-04T16:14:28.009569+09:00 0 [Note] /data/bin/mysqld (mysqld 5.7.19-log) starting as process 137699 ...
2023-01-04T16:14:28.014665+09:00 0 [Note] InnoDB: PUNCH HOLE support available
2023-01-04T16:14:28.014690+09:00 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2023-01-04T16:14:28.014694+09:00 0 [Note] InnoDB: Uses event mutexes
2023-01-04T16:14:28.014699+09:00 0 [Note] InnoDB: GCC builtin __sync_synchronize() is used for memory barrier
2023-01-04T16:14:28.014702+09:00 0 [Note] InnoDB: Compressed tables use zlib 1.2.3
2023-01-04T16:14:28.014706+09:00 0 [Note] InnoDB: Using Linux native AIO
2023-01-04T16:14:28.015218+09:00 0 [Note] InnoDB: Number of pools: 1
2023-01-04T16:14:28.015308+09:00 0 [Note] InnoDB: Using CPU crc32 instructions
2023-01-04T16:14:28.017142+09:00 0 [Note] InnoDB: Initializing buffer pool, total size = 96G, instances = 8, chunk size = 128M
2023-01-04T16:14:32.330216+09:00 0 [Note] InnoDB: Completed initialization of buffer pool
2023-01-04T16:14:32.942852+09:00 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2023-01-04T16:14:32.955591+09:00 0 [Note] InnoDB: Highest supported file format is Barracuda.
2023-01-04T16:14:33.368638+09:00 0 [Note] InnoDB: Log scan progressed past the checkpoint lsn 861023653783
2023-01-04T16:14:33.491857+09:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 861028896256
2023-01-04T16:14:33.560747+09:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 861034139136
2023-01-04T16:14:33.634813+09:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 861039382016
2023-01-04T16:14:33.732145+09:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 861044624896
2023-01-04T16:14:33.809235+09:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 861049867776
2023-01-04T16:14:33.882321+09:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 861055110656
2023-01-04T16:14:33.951426+09:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 861060353536
2023-01-04T16:14:34.018926+09:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 861065596416
2023-01-04T16:14:34.087345+09:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 861070839296
2023-01-04T16:14:34.157479+09:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 861076082176
2023-01-04T16:14:34.222135+09:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 861081325056
2023-01-04T16:14:34.289957+09:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 861086567936
2023-01-04T16:14:34.383546+09:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 861091810816
2023-01-04T16:14:34.428047+09:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 861095311315
2023-01-04T16:14:34.428365+09:00 0 [Note] InnoDB: Database was not shutdown normally!
2023-01-04T16:14:34.428373+09:00 0 [Note] InnoDB: Starting crash recovery.
2023-01-04T16:14:34.664412+09:00 0 [Note] InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percent: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 
2023-01-04T16:14:39.164388+09:00 0 [Note] InnoDB: Apply batch completed
2023-01-04T16:14:39.164433+09:00 0 [Note] InnoDB: Last MySQL binlog file position 0 1770351, file name mysql-bin.002910
2023-01-04T16:14:39.376296+09:00 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2023-01-04T16:14:39.376322+09:00 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2023-01-04T16:14:39.376352+09:00 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2023-01-04T16:14:39.380934+09:00 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2023-01-04T16:14:39.381506+09:00 0 [Note] InnoDB: 96 redo rollback segment(s) found. 96 redo rollback segment(s) are active.
2023-01-04T16:14:39.381516+09:00 0 [Note] InnoDB: 32 non-redo rollback segment(s) are active.
2023-01-04T16:14:39.382232+09:00 0 [Note] InnoDB: Waiting for purge to start
2023-01-04T16:14:39.432361+09:00 0 [Note] InnoDB: 5.7.19 started; log sequence number 861095311315
2023-01-04T16:14:39.432402+09:00 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 6490ms. The settings might not be optimal. (flushed=0 and evicted=0, during the time.)
2023-01-04T16:14:39.433144+09:00 0 [Note] InnoDB: Loading buffer pool(s) from /data/mysqldb_data/ib_buffer_pool
2023-01-04T16:14:39.441399+09:00 0 [ERROR] Function 'federated' already exists
2023-01-04T16:14:39.441413+09:00 0 [Warning] Couldn't load plugin named 'federated' with soname 'ha_federated.so'.
2023-01-04T16:14:39.441750+09:00 0 [Note] Recovering after a crash using /data/mysqldb_logs/binary/mysql-bin
2023-01-04T16:14:39.447539+09:00 0 [Note] Starting crash recovery...
2023-01-04T16:14:39.447569+09:00 0 [Note] Crash recovery finished.
2023-01-04T16:14:39.453180+09:00 0 [Warning] Failed to set up SSL because of the following SSL library error: SSL context is not usable without certificate and private key
2023-01-04T16:14:39.453197+09:00 0 [Note] Server hostname (bind-address): '*'; port: 3306
2023-01-04T16:14:39.453246+09:00 0 [Note] IPv6 is available.
2023-01-04T16:14:39.453257+09:00 0 [Note]   - '::' resolves to '::';
2023-01-04T16:14:39.453273+09:00 0 [Note] Server socket created on IP: '::'.
2023-01-04T16:14:39.475051+09:00 0 [Note] Event Scheduler: Loaded 0 events
2023-01-04T16:14:39.475194+09:00 0 [Note] /data/bin/mysqld: ready for connections.
Version: '5.7.19-log'  socket: '/tmp/mysql.sock'  port: 3306  MySQL Community Server (GPL)
2023-01-04T16:14:39.475230+09:00 0 [Note] Executing 'SELECT * FROM INFORMATION_SCHEMA.TABLES;' to get a list of tables using the deprecated partition engine. You may use the startup option '--disable-partition-engine-check' to skip this check. 
2023-01-04T16:14:39.475234+09:00 0 [Note] Beginning of list of non-natively partitioned tables
2023-01-04T16:14:39.523762+09:00 0 [Note] End of list of non-natively partitioned tables
2023-01-04T16:15:27.809630+09:00 148 [Note] Start binlog_dump to master_thread_id(148) slave_server(101), pos(mysql-bin.002910, 1792665)

 

1. mysql.error 로그 분석

 

이 로그는 InnoDB 스토리지 엔진의 어설션 오류로 인해 2023년 1월 4일 07:14:27 UTC에 MySQL 서버 프로세스가 중단된 것을 보여줍니다
로그는 파일 trx0trx.ic의 line 213의 스레드 140147585529600에서 어설션 오류가 발생했으며
어설션 오류는 !trx-> has_search_latch였습니다. 
트랜잭션에 검색 래치가 있기 때문에 어설션에 실패했습니다. 

(Assertion : 쿼리의 결과를 만족하는지 체크합니다)

오류 메시지는 자세한 버그 보고서를 http://bugs.mysql.com 에 제출하는 것을 권장합니다.

로그에는 mysqld 프로세스가 버그, 이진/라이브러리 손상, 잘못된 구성 또는 하드웨어 오작동을 나타낼 수 있는 

신호 6을 수신했음도 표시됩니다. 
로그는 문제를 진단하기 위해 더 많은 정보를 수집할 것을 제안합니다.

역추적을 통해 close_thread_table, Prepared_stmt_prepare, mysqld_stmt_prepare, 
dispatch_command, do_command 및 handle_connection 함수에서 오류가 발생했음을 알 수 있습니다.

충돌 당시 실행 중인 쿼리는 SELECT DISTINCT CC.*였습니다. 
프로세스가 중지되지 않았으며 mysqld가 다시 시작되었습니다. 

 

 

2.  재시작시 호출한 Query 로그 분석 (DB, was)

 

일단 DB에 select 관련 error 로그는 깨져서 확인이 불가능하고 
Was 쪽 로그를 확인요청해서 받아보니

 

SELECT DISTINCT         
	   CC.*         
...
	   , IF(qYn = 'Y', gdoc, IF(oData = '11', '무>제한', IF(oData > 0, CONCAT(oData, oUnt), gdoc))) AS oData   

...

 

무>제한 ??

이거는 무엇인가;

 

 

개발파트에서 확인 실제 xml을 보니 실제 이런 구문은 없었고.. 뭔가 부등호가 지맘대로 거기 들어가 붙어있었다

(부등호의 순간이동;;)

 

원인을 찾아보니
mybatis 를 사용 중인데 수식에 부등호를 쓰면서 (<![CDATA[  ]]>) 처리하지 않고 그대로 사용한 것으로 확인했다.

(<![CDATA[  ]]>) 쓰지 않을거면 

&lt;
부등호(<)
 
&gt;
부등호(>)

로 치환해서 써야하는데 그렇게 사용하지 않아서 이상한 쿼리를 끝내지 못하고 
결국 프로세스를 재시작하면서 DB가 재시작된 것이다.

근데 저대로면 빌드가 안 되었을텐데... 어떻게 빌드된 파일로 올라갔을까? 

(실제로 개발에서 테스트 했을 때도 빌드에러남ㅋㅋ)

 

3. 해결

문제가 된 query의 부등호 사용 부분을 아래처럼

<![CDATA[

쿼리 내용

]]>

 

CDATA로 감싸서 처리하고 현재까지 DB 재시작이슈는 발생하지 않았다.

 

 

그리고 이번에 발생한 CDATA 이슈에 관해 간략하게 정리한다.

 

4. CDATA  사용관련 내용정리

MyBatis 사용 시 쿼리문에 비교 연산자와 같이 부등호 처리가 필요할 때가 있다.
하지만 비교 연산자를 사용했을 경우 error를 발생시키는데 그 이유는 비교 연산자인지 괄호인지 구분하지 못하기 때문이다.

비교 연산자를 사용했을 때 MyBatis는 괄호인지 비교 연산자인지 구분하지 못한다.
이런 경우에 CDATA를 사용하면 CDATA 안에 들어가는 문장을 문자열로 인식해 구분할 수 있도록 도와준다.

 

 

1) CDATA란?

 

- (Unparsed) Character Data. 다시말하면 파싱하지 않는 문자 데이터 라는 뜻이다.
파싱하는 문자데이터는 PCDATA 라고 부름

 

 

 

2) CDATA를 사용하는 이유?

 

CDATA 안에 쿼리를 사용하면 쿼리 내용의 괄호나 특수문자를 XML parser로 인식하지 않고 "문자열"로 인식한다

쿼리를 작성할 때, '<', '>', '&'를 사용해야하는 경우가 생기는데 xml에서 그냥 사용할 경우 태그로 인식하는 경우가 종종 있다. 
이럴 경우 에러를 뱉어내기 때문에 '태그가 아니라 실제 쿼리에 필요한 코드'라고 알려줘야 한다. 그때 사용하는 것이 <![CDATA[...]]> 이다.

한 마디로 <>(부등호),&(앤드),||(오아) 등을 닫는 부등호가 아니라 문자열로 처리하라는 뜻입니다.
어렵게 말하자면 "XML parser"를 하지 말아라

 

 

3) CDATA 사용방법

 

<![CDATA[

쿼리 내용

]]>

 

4) CDATA를 안 쓸 때 부등호 처리

 

 
” ” : 공백(스페이스 한 칸)을 의미
 
<
부등호(<)
 
&gt;
부등호(>)
 
&amp;
앰퍼샌드(&) 기호
 
&quot;
쌍따옴표(“)
 
&#035;
sharp(#)
 
&#039;
따옴표(‘)

(&lt; 는 Less Than (<, 보다 작은) , &gt; 는 Greater Than (>, 보다 큰) 의 약자라고 한다.)

 

끝.