pajama

Troubleshooting

https://www.ibm.com/support/pages/informix-fails-exception-javasqlsqlexception-blob-not-found

https://www.databaseadm.com/article/11187195/temporary+files+are+not+getting+deleted

안녕하세요. 인포믹스 12.10.FC12, 12.10.FC12W1, 14.10.FC1 버전에서 발생하는 문제를 소개드립니다.

문제가 발생한 이후부터는 인포믹스 프로세스가 시작되지 않으므로 매우 치명적인 결함입니다.

문제가 발생할 수 있는 조건은 아래와 같습니다.

1. 해당 테이블에 VARCHAR 컬럼을 추가한다.

2. 추가한 VARCHAR 컬럼의 사이즈를 축소한다.

위와 같은 상황에서 UPDATE 문장을 실행하면 오류가 발생하면서 인포믹스 프로세스가 다운됩니다.

그러나 항상 다운되는 것은 아니고 대상 테이블에 저장된 데이터 길이에 따라 다운될 수도, 다운되지 않을 수도 있습니다.

아래는 인포믹스 12.10.FC12와 14.10.FC1 버전의 환경에서 다운되는 현상을 재현했을 때의 로그 메시지입니다.

## 12.10.FC12W1

11:20:01  Assert Failed: Buffer modified in inconsistent chunk.

11:20:01  IBM Informix Dynamic Server Version 12.10.FC12W1WE

11:20:01   Who: Session(87, informix@pilma01, 39452766, 700000020593858)

                Thread(222, sqlexec, 700000020553068, 10)

                File: rsdebug.c Line: 1047

11:20:01   Results: Chunk 13 is being taken OFFLINE.

11:20:01   Action: Restore space containing this chunk from the archive.

11:20:01  stack trace for pid 36175890 written to /work2/ifx1210fc12w1we/tmp/af.4c6a350

11:20:02   See Also: /work2/ifx1210fc12w1we/tmp/af.4c6a350, shmem.4c6a350.0

11:20:10  Buffer modified in inconsistent chunk.

11:20:11  Assert Failed: INFORMIX-OnLine Must ABORT

        Critical media failure.

11:20:11  IBM Informix Dynamic Server Version 12.10.FC12W1WE

11:20:11   Who: Session(87, informix@pilma01, 39452766, 700000020593858)

                Thread(222, sqlexec, 700000020553068, 10)

                File: rsmirror.c Line: 2080

11:20:11  stack trace for pid 36175890 written to /work2/ifx1210fc12w1we/tmp/af.4c6a350

11:20:12   See Also: /work2/ifx1210fc12w1we/tmp/af.4c6a350

11:20:19  Thread ID 222 will NOT be suspended because

          it is in a critical section.

11:20:19   See Also: /work2/ifx1210fc12w1we/tmp/af.4c6a350

11:20:19  rsmirror.c, line 2080, thread 222, proc id 36175890, INFORMIX-OnLine Must ABORT

        Critical media failure..

11:20:19  Fatal error in ADM VP at mt_fn.c:14593

11:20:19  Unexpected virtual processor termination: pid = 36175890, exit status = 0x1.

11:20:19  PANIC: Attempting to bring system down

## 14.10.FC1DE

12:46:54  Assert Failed: Buffer modified in inconsistent chunk.

12:46:54  IBM Informix Dynamic Server Version 14.10.FC1DE

12:46:54   Who: Session(46, informix@ifxdb1, 62804, 0x4526fbc8)

                Thread(55, sqlexec, 4522d8c8, 1)

                File: rsdebug.c Line: 908

12:46:54   Results: Chunk 1 is being taken OFFLINE.

12:46:54   Action: Restore space containing this chunk from the archive.

12:46:54  stack trace for pid 62571 written to /opt/IBM/Informix_Software_Bundle/tmp/af.41fb7ad

12:46:54   See Also: /opt/IBM/Informix_Software_Bundle/tmp/af.41fb7ad, shmem.41fb7ad.0

12:46:57  Buffer modified in inconsistent chunk.

12:46:58  Assert Failed: INFORMIX-OnLine Must ABORT

        Critical media failure.

12:46:58  IBM Informix Dynamic Server Version 14.10.FC1DE

12:46:58   Who: Session(46, informix@ifxdb1, 62804, 0x4526fbc8)

                Thread(55, sqlexec, 4522d8c8, 1)

                File: rsmirror.c Line: 2062

12:46:58  stack trace for pid 62571 written to /opt/IBM/Informix_Software_Bundle/tmp/af.41fb7ad

12:46:58   See Also: /opt/IBM/Informix_Software_Bundle/tmp/af.41fb7ad

12:47:02  Thread ID 55 will NOT be suspended because

          it is in a critical section.

12:47:02   See Also: /opt/IBM/Informix_Software_Bundle/tmp/af.41fb7ad

12:47:02  Starting crash time check of:

12:47:02  1. memory block headers

12:47:02  2. stacks

12:47:02  Crash time checking found no problems

12:47:02  rsmirror.c, line 2062, thread 55, proc id 62571, INFORMIX-OnLine Must ABORT

        Critical media failure..

12:47:02  The Master Daemon Died

12:47:02  PANIC: Attempting to bring system down

관련 내용으로 IBM에 기술지원을 요청했었습니다.

해당 문제는 해외에서 발생한 사례가 이미 있었다고 하고 재현 시나리오도 구체적이진 않지만 존재했습니다.

관련 문제를 서술한 문서의 링크는 아래입니다.

http://www-01.ibm.com/support/docview.wss?crawler=1&uid=swg1IT27997

장애 재현시의 메시지 로그에서 보이는 assert failure file 내용을 살펴보니 해당 사용자 스레드의 stack trace를 확인할 수 있었습니다.

0x00000001000af9cc (oninit)afstack

0x00000001000aeb5c (oninit)afhandler

0x00000001000af038 (oninit)affail_interface

0x00000001001b8844 (oninit)buffcheck

0x00000001002371a0 (oninit)buffput

0x0000000100b88640 (oninit)ckpgversion

0x0000000100b87af4 (oninit)rewrecord

0x0000000100b870ec (oninit)rsrewrec

0x000000010071ab00 (oninit)fmrewrec

0x00000001008382a0 (oninit)aud_sqisrewrec

0x0000000100d40a90 (oninit)doupdate

0x0000000100d3ff2c (oninit)chkrowcons

0x000000010114ea04 (oninit)dodmlrow

0x0000000101150eac (oninit)dodelupd

0x000000010083ee30 (oninit)aud_dodelupd

0x0000000100d1ec24 (oninit)excommand

0x00000001008c8590 (oninit)sq_execute

0x00000001008103ac (oninit)sqmain

0x00000001014d6898 (oninit)listen_verify

0x00000001014d530c (oninit)spawn_thread

0x0000000101482ae0 (oninit)th_init_initgls

0x00000001018f86e0 (oninit)startup

defect IT27997에 대해 서술한 내용과 상당히 유사한 stack trace 임을 알 수 있었습니다.

stack trace 중에서 ckpgversion function 부분이 문제인 듯 합니다.

그리고 12.10.FC12 버전부터 In-place alter 기능이 개선되었다고 알려져있는데, 이 개선으로 인해 defect가 발생한 것이 아닌가 생각도 듭니다. 물론 제 추측이기 때문에 정확한 원인으로 보기는 어렵습니다.

IIUG2018의 발표자료중 Jeff McMahon and Nick Geib가 발표한 What’s New in Informix 장표를 살표보면 VARCHAR 에서 VARCHAR 간 (smaller or larger) 사이즈를 변경하는 유형도 In-place alter 방식으로 이루어진다고 나와 있습니다.

아래는 위의 IT27997의 내용을 토대로 작성한 장애재현 스크립트 내용입니다.

테스트용 데이터는 60자 고정길이 필드 한개로 만드시면 재현이 쉽습니다.

drop table test;

create table test (a varchar(60));

load from test.unl insert into test;

alter table test add b int;

alter table test add c varchar(5);

alter table test add d varchar(5);

alter table test add e varchar(5);

alter table test modify c varchar(1);

alter table test modify d varchar(1);

alter table test modify e varchar(1);

update test set a=' qui officia deserunt mollit anim id est laborum.Lorem ip';

해당 문제는 12.10.FC12 및 12.10.FC12W1 에서 발생하는 문제이므로 해당버전을 사용중이라면 IBM에 패치버전을 요청하시거나 12.10.FC11 이하 버전으로 다운그레이드하면 문제가 발생하지 않습니다.

참고가 되시길 바랍니다.

안녕하세요. 2019년 2월 8일자 IBM 알림 메일 내용 중 My notifications의 인포믹스 결함 내용을 소개드립니다.

(IT27956: SYSSESSIONS OCCASIONALLY NOT RETURNING CURRENT SESSION)

CURRENT 세션에 대한 정보가 가끔씩 표시되지 않는 결함에 대한 내용입니다.

보통 내용이 상세하게 설명되지 않은 경우가 많은데, 결함 내용을 재현하기 위한 프로그램 코드도 공개되어 있네요.

코드는 인포믹스를 사용하는 고객에게서 제공되었다고 하네요.

우선 에러에 대한 설명입니다.

Error description

Customers are facing again the problem of missing sessions in
sysmaster:syssessions (as reported in defect idsdb00096417) in
IDS 12.10.FC12W1.
The defect idsdb00096417 should be fixed in IDS 12.10.FC11.
However I am able to reproduce the issue in 12.10.FC10,
12.10.FC11, 12.10.FC12 and 12.10.FC12W1 using the following
reproducing scenario (provided by the customer).

고객사에서 사용중인 인포믹스 버전은 12.10이고 Fix level 까지는 정확히 알 수가 없네요.

다만 내용에서 유추하건데 12.10.FC10 버전에서 위의 현상이 최초로 발견된 것으로 보이고,

12.10.FC12W1 버전에서도 동일하게 재현된다고 하니 2019년 2월 11일 현재까지는 결함이 수정된 버전은 없는 상태입니다.

아래는 재현 시나리오에서 사용한 ESQL/C 코드와 쉘스크립트 내용입니다.

============== test_ec.ec ==============

#include <stdio.h>

$int c, sid;

main()

{

$database stores_demo;

$select DBINFO('sessionid') INTO :sid FROM sysmaster:sysdual;

$select COUNT(*) INTO :c FROM sysmaster:syssessions s WHERE

s.sid = :sid;

if ( c == 0 )

printf("SID: %d Count: %d\n",sid,c);

sleep(1);

}

===================================

============== test_ec_connections.sh ======

#!/bin/bash

LOOP_MAX=$1

while true

do

LOOP=1

while [ $LOOP -le $LOOP_MAX ]

do

./test_ec.exe &

LOOP=`expr $LOOP + 1`

done

sleep 2

date

done

===================================

$ esql -o test_ec.exe test_ec.ec

먼저 test_ec.ec 코드 내용을 살펴보겠습니다.

1. 인포믹스의 stores_demo에 접속

2. 접속한 현재 자신의 세션번호 확인

3. sysmaster:syssessions 테이블에서 자신의 세션번호 갯수 확인

>> 자신의 세션번호 갯수가 0개이면 메시지 출력

너무나 당연하게도 3번에서는 접속이 유지된 상태에서 자신의 세션번호 개수를 확인하는 것이니 1개입니다.

그런데 0개가 나오는 경우가 있다는 건데요.

여기서 이어지는 쉘 스크립트에서는 컴파일된 test_ec 프로그램을 동시에 여러개 실행하는 모양새가 됩니다.

우선은 아래 환경에서 위와 동일한 프로그램으로 테스트를 해봤습니다.

시스템 환경은 아래와 같습니다.

O/S : AIX 6.1

DBMS : Informix 11.50.FC9W3 / 11.70.FC9 / 12.10.FC6WE / 12.10.FC8WE / 12.10.FC12W1WE

문제가 보고된 12.10.FC12 버전에서 실행한 결과입니다.

$ onstat -

IBM Informix Dynamic Server Version 12.10.FC12W1WE -- on-Line -- Up 00:26:56 -- 234320 Kbytes

$ ./test_ec_connetions.sh 10

Mon Feb 11 23:24:22 KORST 2019

...

Mon Feb 11 23:24:47 KORST 2019

Mon Feb 11 23:24:50 KORST 2019

SID: 6081 Count: 0

Mon Feb 11 23:24:52 KORST 2019

SID: 6091 Count: 0

Mon Feb 11 23:24:54 KORST 2019

SID: 6100 Count: 0

Mon Feb 11 23:24:56 KORST 2019

SID: 6111 Count: 0

Mon Feb 11 23:24:58 KORST 2019

SID: 6120 Count: 0

Mon Feb 11 23:25:00 KORST 2019

SID: 6131 Count: 0

Mon Feb 11 23:25:02 KORST 2019

SID: 6140 Count: 0

Mon Feb 11 23:25:04 KORST 2019

SID: 6151 Count: 0

Mon Feb 11 23:25:06 KORST 2019

SID: 6160 Count: 0

Mon Feb 11 23:25:09 KORST 2019

SID: 6171 Count: 0

Mon Feb 11 23:25:11 KORST 2019

Mon Feb 11 23:25:13 KORST 2019

Mon Feb 11 23:25:15 KORST 2019

Mon Feb 11 23:25:17 KORST 2019

Mon Feb 11 23:25:19 KORST 2019

Mon Feb 11 23:25:21 KORST 2019

지속적으로 발생하지 않고 간혹 발생하는데요. 특정 세션 번호만 누락되는 것인지 해서 

아래 조건 절을 생략하고 확인해 봤습니다.

$select DBINFO('sessionid') INTO :sid FROM sysmaster:sysdual;

$select COUNT(*) INTO :c FROM sysmaster:syssessions s WHERE

s.sid = :sid;

if ( c == 0 )     <<  제거한 내용

printf("SID: %d Count: %d\n",sid,c);

$ ./test_ec_connetions.sh 10

SID: 6278 Count: 1

SID: 6279 Count: 1

SID: 6280 Count: 1

SID: 6281 Count: 1

SID: 6282 Count: 1

SID: 6283 Count: 1

SID: 6285 Count: 1

SID: 6284 Count: 1

SID: 6286 Count: 1

SID: 6287 Count: 1

Mon Feb 11 23:32:34 KORST 2019

SID: 6288 Count: 1

SID: 6289 Count: 1

SID: 6291 Count: 0     << 간혹 개수가 확인되지 않는 세션이 존재합니다.

SID: 6290 Count: 1

SID: 6292 Count: 1

SID: 6293 Count: 1

SID: 6294 Count: 1

SID: 6295 Count: 1

SID: 6296 Count: 1

SID: 6297 Count: 1

Mon Feb 11 23:32:36 KORST 2019

SID: 6298 Count: 1

SID: 6299 Count: 1

SID: 6300 Count: 0

SID: 6301 Count: 1

SID: 6302 Count: 1

SID: 6303 Count: 1

SID: 6304 Count: 1

SID: 6305 Count: 1

SID: 6306 Count: 1

SID: 6307 Count: 1

Mon Feb 11 23:32:38 KORST 2019

SID: 6308 Count: 1

SID: 6310 Count: 1

SID: 6309 Count: 1

SID: 6311 Count: 1

SID: 6312 Count: 1

SID: 6313 Count: 1

SID: 6314 Count: 1

SID: 6315 Count: 1

SID: 6316 Count: 1

다른 버전인 11.50과 11.70에서는 재현이 되지 않았습니다.

아직 해당 APAR인 IT27956이 OPEN 상태이므로 곧 해결된 버전이 나오지 않을까 기대해봅니다.

https://www-01.ibm.com/support/entdocview.wss?uid=swg1IT27956

Technote (troubleshooting)

http://www-01.ibm.com/support/docview.wss?uid=swg21648816

Technote (FAQ)

http://www-01.ibm.com/support/docview.wss?uid=swg21323236

인포믹스에 깨진 (일반적으로는 코드셋이 맞지 않은 경우) 문자열이 입력된 경우가 드물게 있습니다. 

10버전 이하에서는 코드셋 확인이 느슨했기 때문에 코드셋이 맞지 않아도 데이터가 입력되는 경우가 있었던 것 같습니다.

또한 TEXT/CLOB 같은 문자열을 저장하기 위한 타입은 데이터베이스 코드셋에 없는 문자열 입력이 가능하므로 이러한 상황이 발생할 여지가 있습니다.

어쨌든 결론적으로 IFX_UNLOAD_EILSEQ_MODE 라는 환경변수를 설정함으로써 코드셋이 맞지 않은 데이터를 UNLOAD할 수 있습니다.

아래 IBM 문서 내용을 참고해주세요.

Use the IFX_UNLOAD_EILSEQ_MODE environment variable to help migrate databases from Informix® Version 10 to Version 11.50 or 11.70, where character data might be encoded with a codeset that is different than the codeset used to create the Version 10 database.

>>-setenv--IFX_UNLOAD_EILSEQ_MODE--value-----------------------><

setenv IFX_UNLOAD_EILSEQ_MODE 1
setenv IFX_UNLOAD_EILSEQ_MODE yes
setenv IFX_UNLOAD_EILSEQ_MODE on

출처

https://www.ibm.com/support/knowledgecenter/ko/SSGU8G_11.70.0/com.ibm.sqlr.doc/ids_sqr_416.htm

Problem(Abstract)

https://www-01.ibm.com/support/docview.wss?uid=swg21450868

Question

From time to time, if an Informix Server crashes, the instance may be left in a state where the Server cannot start, and information about the recovery failure is needed. How can the dba collect information when the database has a failure and cannot recover?

Answer

http://www-01.ibm.com/support/docview.wss?uid=swg21644659

Informix Version : Informix 12.10.FC5W1

OS : Windows 2012 R2

윈도우 2012에 인포믹스 설치 중 아래와 같은 오류가 발생했습니다. 찾아보니 설치프로그램의 호환성 이슈인 것 같습니다. 설치프로그램의 호환 모드를 Windows 7으로 했을 때 잘 설치되었습니다.

The Application has Unexpectedly Quit



Invocation of this Java Application has caused an

Invocation TargetException. This application will not exit (LAX)



ZeroGu6: Windows DLL failed to load
    at ZeroGa4.b(DashoA10*..)
    at ZeroGa4.b(DashoA10*..)
    at com.zerog.ia.installer.LifeCycleManager.b(DashoA10*..)
    at com.zerog.ia.installer.LifeCycleManager.a(DashoA10*..)
    at com.zerog.ia.installer.Main.main(DashoA10*..)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:60)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:37)
    at java.lang.reflect.Method.invoke(Method.java:611)
    at com.zerog.lax.LAX.launch(DashoA10*..)
    at com.zerog.lax.LAX.main(DashoA10*..)

http://www-01.ibm.com/support/docview.wss?uid=swg21686842

Problem(Abstract)

-244 Could not do a physical-order read to fetch next row.
-197 ISAM error: Partition recently appended to; can't open for
write or logging.

Symptom

Cause

Resolving the problem

http://www-01.ibm.com/support/docview.wss?uid=swg21378086