-999 Not implemented yet.

RHEL 8.2 IDS 14.10.FC4W1DE I'm working on a sandbox database, trying to learn some of the new features of 14.10. I've created the instance, created a couple of databases, and loaded some tables into those databases. Now, I'm trying simple SQL statements just to insure that everything looks normal. I can run the following query and get the results shown: select emp_num, firstname, lastname from employee where emp_num = 63;emp_num 63 firstname Adam lastname Adams But if I try to do a simple UPDATE statement, I get this: UPDATE employee SET firstname = "Ansel" WHERE emp_num = 63; #^ # 999: Not implemented yet. # But wait, it gets even weirder. If I repeat the SELECT after receiving the error message above, I get: select emp_num, firstname, lastname from employee where emp_num = 63;emp_num 63 firstname Ansel lastname Adams So it seems that the UPDATE worked, despite the -999 error. I even exited from dbaccess and started a new dbaccess session just to confirm that the updated value is still in the table. It is. Looking at another employee: select emp_num, firstname, lastname from employee where emp_num = 3;emp_num 3 firstname Margaret lastname Bourke-White If I execute a simple DELETE statement, I get: DELETE FROM employee WHERE emp_num = 3;#^ # 999: Not implemented yet. # Repeating the SELECT for this employee: select emp_num, firstname, lastname from employee where emp_num = 3;No rows found. So it did execute the DELETE, even though it returned the -999 error. Once again, I exited dbaccess and started a new dbaccess session, repeating the above SELECT statement, just to confirm that the DELETE executed and the results were committed to the database. What is the cause of this? I've looked in the online.log file, there's nothing there (didn't expect anything, but ...). This is a very simple table, with no opaque data types, no triggers, no foreign keys, and no other table references it as a foreign key. There are five indexes on the table, all btree, all non-unique, non-clustering. I'm directly connected to it, with the dbaccess session running on the same host as the instance, and $INFORMIXSERVER set to the correct value for the instance. ------------------------------ Mark Collins ------------------------------ #Informix

Mark: Yea, something is rather flakey. ------------------------------ Art S. Kagel, President and Principal Consultant ASK Database Management Corp. www.askdbmgt.com ------------------------------

Long shot - try onmode -I 999 and see if there is anything obvious Cheers Paul Paul Watson Oninit LLC +1-913-387-7529 www.oninit.com Oninit® is a registered trademark of Oninit LLC

Paul's suggestion -- onmode -I 999 -- (capital-eye) was also going to be my suggestion, too. One other thing I'd check is that the executables are branded correctly, setuid root where they need to be, correct ownerships, etc. I'd also be curious about what's shown in a dbschema -d [db] -t employee -ss ------------------------------ TOM GIRSCH ------------------------------

I forgot to mention you can set ADEBUG=1 before you start the engine, then the engine should hang on the AF. Very useful at times. Onmode –I will release the 'hang' Cheers Paul

Paul, I ran 'onmode -I -999', then recreated the error. I do not see anything in the DUMPDIR directory, the online.con, or the online.log file. The relevant onconfig parameters are: DUMPDIR $INFORMIXDIR/tmp DUMPSHMEM 2 DUMPGCORE 0 DUMPCORE 0 DUMPCNT 1 ------------------------------Mark Collins ------------------------------

Hmmm, what does onstat –m show ? It should say something like 16:41:22 TrapError set, errno = 271, session_id = -1 16:41:59 Assert Failed: found errno 131 in session 23 16:41:59 Informix Dynamic Server Version 11.70.FC2 16:41:59 Who: Session(23,informix@test , 15625, 169244012) Thread(41, sqlexec, a142adc, 1) File: rsdebug.c Line: 3614 16:41:59 Action: Use onmode -i to allow Dynamic Server to continue 16:43:17 See Also: /tmp/af.4113c17 , shmem.4113c17.0Maybe a -999 is ignored ?? Cheers Paul

Tom, The dbschema output: { TABLE "db_user".employee row size = 1611 number of columns = 325 index size = 66 } create table "db_user".employee ( emp_num smallint, lastname char(30), firstname char(30), middleinit char(30), dob date, age smallint, inpay money(6,2), intimes smallint, inint smallint, address char(35), city char(30), state char(2), zip char(10), ssn char(11), freq char(1), hourly char(1), stat2 money(6,2), retir char(1), insur char(1), adtime smallint, merdis smallint, fed_stat char(1), fed_exemp decimal(3), st_stat char(1), st_exemp decimal(2), flexcalc char(1), addf money(6,2), adds money(6,2), aip decimal(4), prognum char(6), lastadvdate date, nextadvdate date, div char(5), func char(15), class char(5), grade_step integer, payplan char(1), positnum char(8), credun char(8), hlth char(2), dis char(1), hours decimal(6), hourlyrate money(4,2), ovthours decimal(4), suphrlyrate money(4,2), supp money(6,2), normalgros money(8,2), gross money(8,2), totf money(6,2), totf2 money(6,2), fica money(6,2), fed money(6,2), fed2 integer, stat money(6,2), wh5 money(6,2), wh6 money(6,2), wh7 money(6,2), wh8 money(6,2), wh9 money(6,2), wh10 money(10,2), wh11 money(6,2), wh12 money(6,2), wh13 money(6,2), wh14 money(6,2), wh15 money(6,2), wh16 money(6,2), wh17 money(6,2), wh18 money(6,2), wh19 money(6,2), wh20 money(6,2), wh21 money(6,2), wh22 money(6,2), wh23 money(6,2), wh24 money(6,2), wh25 money(6,2), net money(8,2), net2 money(10,2), calcmon money(10,2), calcsix decimal(8), calcthir decimal(8), calcbucket integer, fedwhcalc money(10,2), statwhcalc money(10,2), totflexcalc money(6,2), newretwh money(6,2), oldretwh money(6,2), calcretir money(8,2), swtch char(1), checkdate date, checknum integer, banknum char(2), percent smallint, acct1 decimal(10), amt1 money(8,2), per1 decimal(4), acct2 decimal(10), amt2 money(8,2), per2 decimal(4), acct3 decimal(10), amt3 money(8,2), per3 decimal(4), acct4 decimal(10), amt4 money(8,2), per4 decimal(4), acct5 decimal(10), amt5 money(8,2), per5 decimal(4), amt6 money(8,2), suppind char(1), suppamt money(5,2), tract1 decimal(10), nmil1 smallint, ratem1 decimal(3,3), milamt1 money(6,2), pdamt1 money(6,2), totamt1 money(8,2), tract2 decimal(10), nmil2 smallint, ratem2 decimal(3,3), milamt2 money(6,2), pdamt2 money(6,2), totamt2 money(8,2), tract3 decimal(10), nmil3 smallint, ratem3 decimal(3,3), milamt3 money(6,2), pdamt3 money(6,2), totamt3 money(8,2), tottrav money(8,2), ledgerno char(3), empe_ficapct decimal(4), medic_ficapct decimal(4), supovtpay money(6,2), ovtpay money(6,2), insurtax char(1), dentaltype char(1), taxfc money(6,2), flexdate date, countyno smallint, tips money(6,2), pager char(1), overfica char(1), banknam char(20), bankid char(8), bankck char(1), bankacct char(17), prenotcod char(2), dirdep char(1), lastdddat date, wh5t money(6,2), wh6t money(6,2), wh7t money(6,2), wh8t money(6,2), wh9t money(6,2), wh11t money(6,2), wh13t money(6,2), wh26 money(6,2), wh27 money(6,2), wh28 money(6,2), wh29 money(6,2), wh30 money(6,2), transt money(6,2), visiont money(6,2), wh10t money(6,2), wh12t money(6,2), wh14t money(6,2), wh15t money(6,2), wh16t money(6,2), wh17t money(6,2), wh18t money(6,2), wh19t money(6,2), wh20t money(6,2), splitind char(1), wh31 money(6,2), wh32 money(6,2), wh33 money(6,2), wh34 money(6,2), wh35 money(6,2), wh36 money(6,2), wh37 money(6,2), wh38 money(6,2), wh39 money(6,2), wh40 money(6,2), wh41 money(6,2), wh42 money(6,2), wh43 money(6,2), wh44 money(6,2), wh45 money(6,2), wh46 money(6,2), wh47 money(6,2), wh48 money(6,2), wh49 money(6,2), wh50 money(6,2), wh21t money(6,2), wh22t money(6,2), wh23t money(6,2), wh24t money(6,2), wh25t money(6,2), wh26t money(6,2), wh27t money(6,2), wh28t money(6,2), wh29t money(6,2), wh30t money(6,2), wh31t money(6,2), wh32t money(6,2), wh33t money(6,2), wh34t money(6,2), wh35t money(6,2), wh36t money(6,2), wh37t money(6,2), wh38t money(6,2), wh39t money(6,2), wh40t money(6,2), wh41t money(6,2), wh42t money(6,2), wh43t money(6,2), wh44t money(6,2), wh45t money(6,2), wh46t money(6,2), wh47t money(6,2), wh48t money(6,2), wh49t money(6,2), wh50t money(6,2), wh4 money(6,2), wh4t money(6,2), totcheck money(10,2), retamtset money(8,2), otherearn money(10,2), dirdepcode char(2), lvsort char(5), legl char(1), medc money(6,2), overmedc char(1), lwophrs decimal(6,2), talhrs decimal(6,2), stdhrs decimal(6,2), rounder decimal(12,4), eic money(6,2), incre smallint, dkflag char(2), trans money(6,2), vision money(8,2), visiontype char(2), depend char(2), termdate date, education char(1), child_life char(2), spend_type char(2), std_wait char(2), dfc2 money(8,2), spa2 money(8,2), dl2 money(8,2), ltc money(8,2), dfc2t money(8,2), spa2t money(8,2), dl2t money(8,2), ltct money(8,2), ltctype char(1), basepay money(10,2), salsupp money(8,2), deptid char(10), ers_num char(8), hiredate date, specill money(8,2), spcicode char(2), wspit money(8,2), mvsupp money(8,2), mvsuppann money(8,2), totperpay money(8,2), gender char(1), rectype char(4), rectypdat date, nsf char(1), pullflag char(1), suffix char(3), add2 char(35), erschandat date, erscode char(2), interadd char(50), internafl char(1), ersperc decimal(4), paytype char(2), erseffdat date, jobcode char(2), shbpelig char(1), spci2code char(2), specill2 money(8,2), spa3 money(8,2), hltsav money(8,2), spi2t money(8,2), spa3t money(8,2), hltsat money(8,2), division char(3), tdirdep char(1), banknum2 char(2), banknam2 char(20), bankid2 char(8), bankck2 char(1), bankacct2 char(17), prenotcod2 char(2), lastdddat2 date, ograde_step char(5), furpay money(10,2), furcode integer, tra char(1), gsepper decimal(5,2), cktype char(1), per457 decimal(5,2), per401 decimal(5,2), ddapprove char(1), ddappr_date date, ddctrycode char(3), tddapprove char(1), tddappr_date date, tddctrycode char(3), email char(72), rehire_date date, rehire char(1), jobstat char(1), origbasepay money(16,2), origsalsupp money(16,2), ppsup money(6,2), eict money(6,2), flsa money(8,2), gsepded char(1) ) extent size 2000 next size 150 lock mode row; revoke all on "db_user".employee from "public" as "db_user";create index "db_user".emp_calc on "db_user".employee (calcretir) using btree in indexdbs; create index "db_user".emp_ers on "db_user".employee (ers_num) using btree in indexdbs; create index "db_user".emp_grad on "db_user".employee (grade_step) using btree in indexdbs; create index "db_user".emp_incre on "db_user".employee (incre) using btree in indexdbs; create index "db_user".emp_prog on "db_user".employee (prognum) using btree in indexdbs; create index "db_user".emp_ssn on "db_user".employee (ssn) using btree in indexdbs; create trigger "db_user".empl_reg_usr_ins insert on "db_user".employee referencing new as n for each row ( execute procedure user_audit_db:"db_user".empl_reg_usr_ins_spl(n.ers_num ,"db_user".curr_region(),n.ssn ,n.lastname ,n.firstname ,n.middleinit ,n.suffix ,n.email ,n.freq ));create trigger "db_user".empl_reg_usr_upd update of ers_num,ssn, lastname,firstname,middleinit,suffix,email,freq on "db_user" .employee referencing old as o new as n for each row ( execute procedure user_audit_db:"db_user".empl_reg_usr_upd_spl(n.ers_num ,"db_user".curr_region(),n.ssn ,n.lastname ,n.firstname ,n.middleinit ,n.suffix ,n.email ,n.freq ));create trigger "db_user".empl_reg_usr_del delete on "db_user".employee referencing old as o for each row ( execute procedure user_audit_db:"db_user".empl_reg_usr_del_spl(o.ers_num ,"db_user".curr_region(),o.ssn ));I have confirmed that the procedures empl_reg_usr_del_spl, empl_reg_usr_ins_spl, and empl_reg_usr_upd_spl all are present in the user_audit_db, and all are owned by user "db_user". Also, "public" has execute permission on all three of these procedures. ------------------------------ Mark Collins ------------------------------

Nothing in onstat -m other than Checkpoint Complete messages like these: 02/01/2021 10:13:50 Checkpoint Completed: duration was 0 seconds. 02/01/2021 10:13:50 Mon Feb 1 - loguniq 68, logpos 0x823018, timestamp: 0x230a5df Interval: 694 02/01/2021 10:13:50 Maximum server connections 2 02/01/2021 10:13:50 Checkpoint Statistics - Avg. Txn Block Time 0.000, # Txns blocked 0, Plog used 0, Llog used 2 02/01/2021 10:18:51 Checkpoint Completed: duration was 0 seconds. 02/01/2021 10:18:51 Mon Feb 1 - loguniq 68, logpos 0x85b018, timestamp: 0x230aaa3 Interval: 695 02/01/2021 10:18:51 Maximum server connections 2 02/01/2021 10:18:51 Checkpoint Statistics - Avg. Txn Block Time 0.000, # Txns blocked 0, Plog used 157, Llog used 56 02/01/2021 10:33:50 Checkpoint Completed: duration was 0 seconds. 02/01/2021 10:33:50 Mon Feb 1 - loguniq 68, logpos 0x863018, timestamp: 0x230ab5c Interval: 696 ------------------------------ Mark Collins ------------------------------

I have seen some errors being ignored via the onmode –I - you can check easier enough, run onmode –I 201 and then use dbaccess to generate a syntax error Cheers Paul

well, I must have done it wrong the first time, because I repeated the 'onmode -I -999', repeated the steps to create the error, and now the 'onstat -m' shows: 02/01/2021 11:04:32 Verbose error trapping set, errno = 999, session_id = -1 02/01/2021 11:04:57 Assert Failed: found errno 999 in session 126 02/01/2021 11:04:57 IBM Informix Dynamic Server Version 14.10.FC4W1DE 02/01/2021 11:04:57 Who: Session(126, informix@gsvgsandbox02.smi.corp , 766050, 0x4de391d8) Thread(495, sqlexec, 4dde7e48, 8) File: rsdebug.c Line: 3052 02/01/2021 11:04:57 Action: Use onmode -I to stop verbose error trapping. 02/01/2021 11:04:57 stack trace for pid 652898 written to /informix/current/tmp/af.5d726a9 02/01/2021 11:04:57 See Also: /informix/current/tmp/af.5d726a9, shmem.5d726a9.0 02/01/2021 11:05:00 found errno 999 in session 126 02/01/2021 11:05:00 invoke_alarm(): /bin/sh -c '/informix/current/etc/alarmprogram.sh 3 6 "Internal Subsystem failure: 'MT'" "found errno 999 in session 126" "" 6300' 02/01/2021 11:05:00 invoke_alarm(): mt_exec failed, status -1, errno 0 Looking in DUMPDIR at the file af.5d726a9, I see: 11:04:57 11:04:57 IBM Informix Dynamic Server Version 14.10.FC4W1DE 11:04:57 Assert Failed: found errno 999 in session 126 11:04:57 Who: Session(126, informix@sandbox.our.company , 766050, 0x4de391d8) Thread(495, sqlexec, 4dde7e48, 8) File: rsdebug.c Line: 3052 11:04:57 Action: Use onmode -I to stop verbose error trapping. 11:04:57 SHM Globals and Master Pool/Master Block Adresses: 11:04:57 shmcb = 0x000000004419ee88 11:04:57 rhead = 0x000000004420c800 11:04:57 pool list = 0x000000004419ef60 11:04:57 block pool list = 0x0000000044206768 11:04:57 TRANSP = 0x000000004de391d8 11:04:57 PARTP = 0x00000000521fc028 11:04:57 PARTNP = 0x00000000521fc140 11:04:57 OPENP = 0x0000000050cae028 11:04:57 FILEP = 0x0000000050caeea0 11:04:57 Raw hex dump of stack located in /informix/current/tmp/af.5d726a9.rawstk 11:04:57 Stack for thread: 495 sqlexecbase: 0x0000000050b71000 len: 102400 pc: 0x00000000014a458d tos: 0x0000000050b86560 state: running vp: 8 0x00000000014a458d (oninit) afstack 0x00000000014a962d (oninit) afhandler 0x00000000014a9c42 (oninit) affail_interface 0x0000000000ed9a00 (oninit) check_traperror 0x0000000000762a41 (oninit) sqerr 0x000000000079240a (oninit) getaggbyname 0x00000000006c2a20 (oninit) agg2expr 0x00000000006c0ffc (oninit) expr2expr 0x00000000006db4a5 (oninit) ip_exprparse 0x00000000006e433b (oninit) ip_evalexpr 0x00000000006ed6fa (oninit) runproc 0x00000000006f10e3 (oninit) udrlm_spl_execute 0x0000000000aff1f0 (oninit) udrlm_exec_routine 0x000000000072d96d (oninit) udr_execute 0x00000000007339a6 (oninit) exroutine 0x00000000006093bc (oninit) execproc 0x000000000071b91e (oninit) aud_execproc 0x000000000060c013 (oninit) excommand 0x000000000091cc90 (oninit) dotrstmts 0x0000000000920d5b (oninit) dotrigs 0x00000000009240dd (oninit) ferafttrig 0x0000000000916555 (oninit) dodmlrow 0x0000000000918604 (oninit) dodelupd 0x000000000060d45e (oninit) excommand 0x0000000000abb3eb (oninit) sq_execute_workhorse 0x0000000000abbc2d (oninit) sq_execute 0x0000000000b8eeae (oninit) sqmain 0x00000000015d2e3b (oninit) spawn_thread 0x0000000001495103 (oninit) th_init_initgls 0x00000000014dc0bf (oninit) startup siginfo: <NULL> 11:04:57 See Also: /informix/current/tmp/af.5d726a9, shmem.5d726a9.0 ------------------------------Begin System Alarm Program Output ------------------------------ Assertion Failure Type: FAILURE Host Name: sandbox.our.company Database Server Name: ol_informix1410 Time of failure: Mon Feb 1 11:04:57 EST 2021 AF file: /informix/current/tmp/af.5d726a9 Shared memory file: None System Blocking: OFF ===========------------- - - - - - - tail -100 /informix/current/ol_informix1410.log: 02/01/2021 08:33:50 Checkpoint Completed: duration was 0 seconds. 02/01/2021 08:33:50 Mon Feb 1 - loguniq 68, logpos 0x7cd018, timestamp: 0x2309f63 Interval: 685 02/01/2021 08:33:50 Maximum server connections 2 02/01/2021 08:33:50 Checkpoint Statistics - Avg. Txn Block Time 0.000, # Txns blocked 0, Plog used 12, Llog used 2 02/01/2021 08:38:50 Checkpoint Completed: duration was 0 seconds. 02/01/2021 08:38:50 Mon Feb 1 - loguniq 68, logpos 0x7d5018, timestamp: 0x2309fc3 Interval: 686 02/01/2021 08:38:50 Maximum server connections 2 02/01/2021 08:38:50 Checkpoint Statistics - Avg. Txn Block Time 0.000, # Txns blocked 0, Plog used 15, Llog used 8 02/01/2021 08:48:50 Checkpoint Completed: duration was 0 seconds. 02/01/2021 08:48:50 Mon Feb 1 - loguniq 68, logpos 0x7d7018, timestamp: 0x2309fd2 Interval: 687 02/01/2021 08:48:50 Maximum server connections 2 02/01/2021 08:48:50 Checkpoint Statistics - Avg. Txn Block Time 0.000, # Txns blocked 0, Plog used 12, Llog used 2 02/01/2021 09:03:50 Checkpoint Completed: duration was 0 seconds. 02/01/2021 09:03:50 Mon Feb 1 - loguniq 68, logpos 0x7d9018, timestamp: 0x2309fe3 Interval: 688 02/01/2021 09:03:50 Maximum server connections 2 02/01/2021 09:03:50 Checkpoint Statistics - Avg. Txn Block Time 0.000, # Txns blocked 0, Plog used 3, Llog used 2 02/01/2021 09:18:50 Checkpoint Completed: duration was 0 seconds. 02/01/2021 09:18:50 Mon Feb 1 - loguniq 68, logpos 0x80e018, timestamp: 0x230a4a3 Interval: 689 02/01/2021 09:18:50 Maximum server connections 2 02/01/2021 09:18:50 Checkpoint Statistics - Avg. Txn Block Time 0.000, # Txns blocked 0, Plog used 148, Llog used 53 02/01/2021 09:33:50 Checkpoint Completed: duration was 0 seconds. 02/01/2021 09:33:50 Mon Feb 1 - loguniq 68, logpos 0x810018, timestamp: 0x230a4b7 Interval: 690 02/01/2021 09:33:50 Maximum server connections 2 02/01/2021 09:33:50 Checkpoint Statistics - Avg. Txn Block Time 0.000, # Txns blocked 0, Plog used 12, Llog used 2 02/01/2021 09:38:50 Checkpoint Completed: duration was 0 seconds. 02/01/2021 09:38:50 Mon Feb 1 - loguniq 68, logpos 0x81d400, timestamp: 0x230a57c Interval: 691 02/01/2021 09:38:50 Maximum server connections 2 02/01/2021 09:38:50 Checkpoint Statistics - Avg. Txn Block Time 0.000, # Txns blocked 0, Plog used 25, Llog used 13 02/01/2021 09:48:50 Checkpoint Completed: duration was 0 seconds. 02/01/2021 09:48:50 Mon Feb 1 - loguniq 68, logpos 0x81f018, timestamp: 0x230a58b Interval: 692 02/01/2021 09:48:50 Maximum server connections 2 02/01/2021 09:48:50 Checkpoint Statistics - Avg. Txn Block Time 0.000, # Txns blocked 0, Plog used 19, Llog used 2 02/01/2021 10:03:50 Checkpoint Completed: duration was 0 seconds. 02/01/2021 10:03:50 Mon Feb 1 - loguniq 68, logpos 0x821018, timestamp: 0x230a59c Interval: 693 02/01/2021 10:03:50 Maximum server connections 2 02/01/2021 10:03:50 Checkpoint Statistics - Avg. Txn Block Time 0.000, # Txns blocked 0, Plog used 3, Llog used 2 02/01/2021 10:13:50 Checkpoint Completed: duration was 0 seconds. 02/01/2021 10:13:50 Mon Feb 1 - loguniq 68, logpos 0x823018, timestamp: 0x230a5df Interval: 694 02/01/2021 10:13:50 Maximum server connections 2 02/01/2021 10:13:50 Checkpoint Statistics - Avg. Txn Block Time 0.000, # Txns blocked 0, Plog used 0, Llog used 2 02/01/2021 10:18:51 Checkpoint Completed: duration was 0 seconds. 02/01/2021 10:18:51 Mon Feb 1 - loguniq 68, logpos 0x85b018, timestamp: 0x230aaa3 Interval: 695 02/01/2021 10:18:51 Maximum server connections 2 02/01/2021 10:18:51 Checkpoint Statistics - Avg. Txn Block Time 0.000, # Txns blocked 0, Plog used 157, Llog used 56 02/01/2021 10:33:50 Checkpoint Completed: duration was 0 seconds. 02/01/2021 10:33:50 Mon Feb 1 - loguniq 68, logpos 0x863018, timestamp: 0x230ab5c Interval: 696 02/01/2021 10:33:50 Maximum server connections 2 02/01/2021 10:33:50 Checkpoint Statistics - Avg. Txn Block Time 0.000, # Txns blocked 0, Plog used 22, Llog used 8 02/01/2021 10:38:51 Checkpoint Completed: duration was 0 seconds. 02/01/2021 10:38:51 Mon Feb 1 - loguniq 68, logpos 0x876520, timestamp: 0x230ad68 Interval: 697 02/01/2021 10:38:51 Maximum server connections 2 02/01/2021 10:38:51 Checkpoint Statistics - Avg. Txn Block Time 0.000, # Txns blocked 0, Plog used 63, Llog used 19 02/01/2021 10:48:51 Checkpoint Completed: duration was 0 seconds. 02/01/2021 10:48:51 Mon Feb 1 - loguniq 68, logpos 0x878018, timestamp: 0x230ad77 Interval: 698 02/01/2021 10:48:51 Maximum server connections 2 02/01/2021 10:48:51 Checkpoint Statistics - Avg. Txn Block Time 0.000, # Txns blocked 0, Plog used 11, Llog used 2 02/01/2021 11:03:51 Checkpoint Completed: duration was 0 seconds. 02/01/2021 11:03:51 Mon Feb 1 - loguniq 68, logpos 0x87a018, timestamp: 0x230ad89 Interval: 699 02/01/2021 11:03:51 Maximum server connections 2 02/01/2021 11:03:51 Checkpoint Statistics - Avg. Txn Block Time 0.000, # Txns blocked 0, Plog used 3, Llog used 2 02/01/2021 11:04:32 Verbose error trapping set, errno = 999, session_id = -1 02/01/2021 11:04:57 Assert Failed: found errno 999 in session 126 02/01/2021 11:04:57 IBM Informix Dynamic Server Version 14.10.FC4W1DE 02/01/2021 11:04:57 Who: Session(126, informix@sandbox.our.company , 766050, 0x4de391d8) Thread(495, sqlexec, 4dde7e48, 8) File: rsdebug.c Line: 3052 02/01/2021 11:04:57 Action: Use onmode -I to stop verbose error trapping. 02/01/2021 11:04:57 stack trace for pid 652898 written to /informix/current/tmp/af.5d726a9 02/01/2021 11:04:57 See Also: /informix/current/tmp/af.5d726a9, shmem.5d726a9.0 ===========------------- - - - - - - /informix/current/bin/onstat -g ath: IBM Informix Dynamic Server Version 14.10.FC4W1DE -- On-Line -- Up 2 days 18:02:25 -- 916652 Kbytes Threads:tid tcb rstcb prty status vp-class name 2 50489148 0 1 IO Idle 3lio* lio vp 0 3 504aa3d8 0 1 IO Idle 4pio* pio vp 0 4 504cb3d8 0 1 IO Idle 5aio* aio vp 0 5 504ec3d8 1f4f6c0 1 IO Idle 6msc* msc vp 0 6 5051d3d8 0 1 IO Idle 7fifo* fifo vp 0 7 505b6050 0 1 IO Idle 11aio* aio vp 1 8 505d7720 4dde4028 3 sleeping secs: 1 9cpu main_loop() 9 506526b8 0 1 running 12soc* soctcppoll 10 506748b0 0 2 sleeping forever 1cpu* soctcplst 11 506a6370 0 2 sleeping forever 8cpu* soctcplst 12 506d3a00 0 2 sleeping forever 9cpu* soctcplst 13 50700418 4dde4908 1 sleeping secs: 1 8cpu flush_sub(0) 14 50700758 4dde51e8 1 sleeping secs: 1 9cpu flush_sub(1) 15 50700a98 0 3 IO Idle 1cpu* kaio 16 507ef550 0 3 IO Idle 8cpu* kaio 17 508120d0 4dde5ac8 2 sleeping secs: 1 9cpu aslogflush 18 508b0178 4dde63a8 1 sleeping secs: 92 1cpu btscanner_0 19 508cd370 4dde6c88 3 cond wait ReadAhead 1cpu readahead_0 20 508e9568 4dde7568 3 sleeping secs: 1 9cpu auto_tune 87 521c0028 0 3 IO Idle 9cpu* kaio 88 52546b50 4de0ad68 3 sleeping secs: 1 1cpu* onmode_mon 89 5259e028 4dde8728 3 sleeping secs: 1 9cpu periodic 90 52781bf8 4de04bc8 3 sleeping forever 1cpu memory 91 5206d028 4de07828 3 sleeping secs: 18 9cpu session_mgr 101 52461d48 4de08108 1 sleeping secs: 1 9cpu dbutil 102 52676d48 4de0a488 1 sleeping secs: 124 8cpu dbScheduler 103 52272d48 0 3 IO Idle 10cpu* kaio 104 51f047f0 4de092c8 1 sleeping forever 1cpu dbWorker1 105 51f67a10 4de06668 1 sleeping forever 8cpu dbWorker2 108 5211f370 4de09ba8 1 cond wait bp_cond 9cpu bf_priosweep() *495 50b9a028 4dde7e48 1 running 8cpu sqlexec ===========------------- - - - - - - /informix/current/bin/onstat -g stk 495 light: IBM Informix Dynamic Server Version 14.10.FC4W1DE -- On-Line -- Up 2 days 18:02:25 -- 916652 KbytesStack for thread: 495 sqlexecbase: 0x0000000050b71000 len: 102400 pc: 0x00000000014ac3fa tos: 0x0000000050b86b90 state: running vp: 8 0x00000000014ac3fa (oninit) mt_system 0x00000000014a7dbd (oninit) afhandler 0x00000000014a9c42 (oninit) affail_interface 0x0000000000ed9a00 (oninit) check_traperror 0x0000000000762a41 (oninit) sqerr 0x000000000079240a (oninit) getaggbyname 0x00000000006c2a20 (oninit) agg2expr 0x00000000006c0ffc (oninit) expr2expr 0x00000000006db4a5 (oninit) ip_exprparse 0x00000000006e433b (oninit) ip_evalexpr 0x00000000006ed6fa (oninit) runproc 0x00000000006f10e3 (oninit) udrlm_spl_execute 0x0000000000aff1f0 (oninit) udrlm_exec_routine 0x000000000072d96d (oninit) udr_execute 0x00000000007339a6 (oninit) exroutine 0x00000000006093bc (oninit) execproc 0x000000000071b91e (oninit) aud_execproc 0x000000000060c013 (oninit) excommand 0x000000000091cc90 (oninit) dotrstmts 0x0000000000920d5b (oninit) dotrigs 0x00000000009240dd (oninit) ferafttrig 0x0000000000916555 (oninit) dodmlrow 0x0000000000918604 (oninit) dodelupd 0x000000000060d45e (oninit) excommand 0x0000000000abb3eb (oninit) sq_execute_workhorse 0x0000000000abbc2d (oninit) sq_execute 0x0000000000b8eeae (oninit) sqmain 0x00000000015d2e3b (oninit) spawn_thread 0x0000000001495103 (oninit) th_init_initgls 0x00000000014dc0bf (oninit) startup ===========------------- - - - - - - /informix/current/bin/onstat -u: IBM Informix Dynamic Server Version 14.10.FC4W1DE -- On-Line -- Up 2 days 18:02:26 -- 916652 KbytesUserthreads address flags sessid user tty wait tout locks nreads nwrites 4dde4028 ---P--D 1 informix - 0 0 0 147 13091 4dde4908 ---P--F 0 informix - 0 0 0 0 18114 4dde51e8 ---P--F 0 informix - 0 0 0 0 1070 4dde5ac8 ---P--- 9 informix - 0 0 0 0 0 4dde63a8 ---P--B 10 informix - 0 0 0 125 256 4dde6c88 Y--P--D 11 informix - 508b0560 0 0 9978 0 4dde7568 ---P--D 12 informix - 0 0 0 0 0 4dde7e48 *--BP--- 126 informix 2 0 0 10 0 0 4dde8728 ---P--D 78 informix - 0 0 0 2 0 4de04bc8 ---P--D 79 informix - 0 0 0 0 0 4de06668 ---P--- 93 informix - 0 0 1 1673 1707 4de07828 ---P--D 80 informix - 0 0 0 0 0 4de08108 ---P--- 90 informix - 0 0 1 14 0 4de092c8 ---P--- 92 informix - 0 0 1 1906 2618 4de09ba8 Y--P--D 96 informix - 4429cd48 0 0 0 0 4de0a488 ---P--- 91 informix - 0 0 2 284 885 4de0ad68 ---P--D 77 informix - 0 0 0 0 0 17 active, 128 total, 70 maximum concurrent ===========------------- - - - - - - /informix/current/bin/onstat -g ses 126: IBM Informix Dynamic Server Version 14.10.FC4W1DE -- On-Line -- Up 2 days 18:02:26 -- 916652 Kbytessession effective #RSAM total used dynamic id user user tty pid hostname threads memory memory explain 126 informix - 2 766050 sandbox.our.company 1 245760 236272 off Program : /informix/IDS14.10.FC4W1/bin/dbaccess tid name rstcb flags curstk status 495 sqlexec 4dde7e48 --BP--- 13424 running- Memory pools count 2 name class addr totalsize freesize #allocfrag #freefrag 126 V 50e0c040 241664 8744 209 11 126*O0 V 52b3c040 4096 744 1 1 name free used name free used overhead 0 6704 scb 0 144 opentable 0 14616 filetable 0 2648 ru 0 600 log 0 16536 temprec 0 7328 ralloc 0 137144 gentcb 0 1600 ostcb 0 2992 sqscb 0 24448 sql 0 3184 hashfiletab 0 552 osenv 0 2576 buft_buffer 0 1816 sqtcb 0 9920 fragman 0 2968 sapi 0 288 udr 0 208 sqscb info scb sqscb optofc pdqpriority optcompind directives 4e7901c0 50c50028 0 0 2 1 Sess SQL Current Iso Lock SQL ISAM F.E. Id Stmt type Database Lvl Mode ERR ERR Vers Explain 126 user_auth_db CR Not Wait -999 0 9.24 Off Stored procedure stack : context proc-counter opcode name ------------------------------ 0x0000000052a75c48 0x52a585e0+0x0010 EXPR user_auth_db:empl_reg_usr_del_spl Current SQL statement (3) in procedure user_auth_db:empl_reg_usr_del_spl proc-counter 0x52a585e0 opcode EXPR (<procedure> strip_dashes, i_ssn) Last parsed SQL statement : delete from employee where emp_num = 63===========------------- - - - - - - /informix/current/bin/onstat -g env 126: IBM Informix Dynamic Server Version 14.10.FC4W1DE -- On-Line -- Up 2 days 18:02:26 -- 916652 Kbytes . . .This goes on for about 53k lines, so not sure how much of that you want to see, or if there are specific sections that you think might be more likely to point to the problem. ------------------------------ Mark Collins

Very had to read ...... Why is the stack showing udr_execute, AFAIK that path should only be for non-standard datatypes. Thought we were doing a simple update Cheers Paul

Problem looking to be an aggregate function called from within the trigger UDR now being a remote aggregate function (residing in a different database). Might simply be a consequence of the UDRs themselves residing in different DB? ------------------------------ Andreas Legner ------------------------------

Search for the "onstat –g ses 126" in that af file.

===========------------- - - - - - - /informix/current/bin/onstat -g ses 126: IBM Informix Dynamic Server Version 14.10.FC4W1DE -- On-Line -- Up 2 days 18:02:26 -- 916652 Kbytessession effective #RSAM total used dynamic id user user tty pid hostname threads memory memory explain 126 informix - 2 766050 sandbox02.our.company 1 245760 236272 off Program : /informix/IDS14.10.FC4W1/bin/dbaccess tid name rstcb flags curstk status 495 sqlexec 4dde7e48 --BP--- 13424 running- Memory pools count 2 name class addr totalsize freesize #allocfrag #freefrag 126 V 50e0c040 241664 8744 209 11 126*O0 V 52b3c040 4096 744 1 1 name free used name free used overhead 0 6704 scb 0 144 opentable 0 14616 filetable 0 2648 ru 0 600 log 0 16536 temprec 0 7328 ralloc 0 137144 gentcb 0 1600 ostcb 0 2992 sqscb 0 24448 sql 0 3184 hashfiletab 0 552 osenv 0 2576 buft_buffer 0 1816 sqtcb 0 9920 fragman 0 2968 sapi 0 288 udr 0 208 sqscb info scb sqscb optofc pdqpriority optcompind directives 4e7901c0 50c50028 0 0 2 1 Sess SQL Current Iso Lock SQL ISAM F.E. Id Stmt type Database Lvl Mode ERR ERR Vers Explain 126 user_auth_db CR Not Wait -999 0 9.24 Off Stored procedure stack : context proc-counter opcode name ------------------------------ 0x0000000052a75c48 0x52a585e0+0x0010 EXPR user_auth_db:empl_reg_usr_del_spl Current SQL statement (3) in procedure user_auth_db:empl_reg_usr_del_spl proc-counter 0x52a585e0 opcode EXPR (<procedure> strip_dashes, i_ssn) Last parsed SQL statement : delete from employee where emp_num = 63===========------------- - - - - - - /informix/current/bin/onstat -g env 126: IBM Informix Dynamic Server Version 14.10.FC4W1DE -- On-Line -- Up 2 days 18:02:26 -- 916652 KbytesEnvironment for session 126: Variable Value [values-list] CLIENT_LOCALE en_US.8859-1 CLNT_PAM_CAPABLE 1 DBDELIMITER | DBPATH . [.] [//ol_informix1410] DBPRINT lp -s DBTEMP /tmp GL_USEGLU 1 IGNORE_UNDERFLOW 1 INFORMIXDIR /informix/current [/informix/current] [/usr/informix] INFORMIXSERVER ol_informix1410 INFORMIXSQLHOSTS /informix/current/etc/sqlhosts.ol_informix1410 INFORMIXTERM terminfo LANG en_US.UTF-8 LC_COLLATE en_US.UTF-8 LC_CTYPE en_US.UTF-8 LC_MONETARY en_US.UTF-8 LC_NUMERIC en_US.UTF-8 LC_TIME en_US.UTF-8 LKNOTIFY yes LOCKDOWN no NODEFDAC no [no] [no] ONCONFIG onconfig.ol_informix1410 PATH /informix/current/bin:/informix/current/extend/krakatoa/jre /bin:/informix/current/bin:/informix/current/extend/krakat oa/jre/bin:/home/informix/.local/bin:/home/informix/bin:/u sr/local/bin:/usr/bin:/usr/local/sbin:/usr/sbin:/smile/con fig SERVER_LOCALE en_US.819 SHELL /bin/bash SUBQCACHESZ 10 TERM xterm [xterm] [dumb] TERMCAP /etc/termcap ===========------------- - - - - - - /informix/current/bin/onstat -g sql 126: IBM Informix Dynamic Server Version 14.10.FC4W1DE -- On-Line -- Up 2 days 18:02:26 -- 916652 KbytesSess SQL Current Iso Lock SQL ISAM F.E. Id Stmt type Database Lvl Mode ERR ERR Vers Explain 126 user_auth_db CR Not Wait -999 0 9.24 Off Stored procedure stack : context proc-counter opcode name ------------------------------ 0x0000000052a75c48 0x52a585e0+0x0010 EXPR user_auth_db:empl_reg_usr_del_spl Current SQL statement (3) in procedure user_auth_db:empl_reg_usr_del_spl proc-counter 0x52a585e0 opcode EXPR (<procedure> strip_dashes, i_ssn) Last parsed SQL statement : delete from employee where emp_num = 63===========------------- - - - - - - /informix/current/bin/onstat -g stm 126: IBM Informix Dynamic Server Version 14.10.FC4W1DE -- On-Line -- Up 2 days 18:02:26 -- 916652 Kbytes session 126 ---------------------------------------------------------------sdblock heapsz flags statement ('*' = Open cursor) 52d17028 72528 ----- delete from employee where emp_num = 63 52d172e8 51760 ----- <SPL(user_db:567), stmt(0):SELECT > 52d175a8 4976 ----- <SPL(user_auth_db:561), stmt(1):EXPRESSION > ===========------------- - - - - - - ------------------------------ Mark Collins ------------------------------

I believe that is due to the triggers calling stored procedures that reside in a different database (user_auth_db vs. user_db). I have disabled the triggers on the employee table, and now I am able to update and delete rows without the -999 error. This sandbox instance was created by dbexport a few databases from our existing instance and dbimporting them into the new instance, so it is likely that I've missed some component that is necessary for the whole thing to work. I will be looking at the triggers in more detail now, insuring that all of their dependencies are in place. Thanks to all for the help in getting this far. ------------------------------ Mark Collins ------------------------------

I'm not certain whether it is that the triggers call procedures that reside in a different database, or if there is something else that is missing. The current 11.50 production database, on which this sandbox is based, does have the triggers calling procedures in remote databases, so I know that part was working in 11.50. I will be looking at these in more detail now to see what, if anything, I missed in trying to recreate the environment in the sandbox. Thanks for pointing me in the correct direction. ------------------------------ Mark Collins ------------------------------

Onmode –I and stack traces are your friend J

Found it. The trigger calls a procedure in a remote database. So far so good. That procedure then invokes a function to strip off the '(', ')', and '-' from telephone numbers. That function did not exist in the remote database. Added it, and now updates and deletes against the employee table work just fine with the triggers enabled. So in this case, the -999 was referring to a user-defined function that was not defined. ------------------------------ Mark Collins ------------------------------

So -999 was accurate then Cheers Paul