fetch column metadata error

Issue #1 resolved
Aaron Bartell created an issue

Experiencing the intermittent ibm_db error, as detailed below.

An unexpected error occurred during data retrieval: An unexpected error occurred during data retrieval: uncaught throw :"Fetch Failure: <error message could not be retrieved>"

What's interesting is it will fail at different spots on the page when rapid refreshing (to reproduce the error). For example, in the below code it will sometimes fail on users.each and other times on u.name.

  <% users.each do |u| %> 
        <%= u.name %>

The LUW (Linux/Unix/Windows) version of ibm_db also has this issue.

Working to reproduce issue with PASE CLI tool (thanks Tony Cairns).

Example of running

paseclitrace.ini:

; device_type=[tty,file]
;   0  - console
;   1  - file (/tmp/libdb400_trace)
; device_pid (device_type=1-file)
;   0 - /tmp/libdb400_trace
;   1 - /tmp/libdb400_trace[_pid]
; trace_type
;   0 - trace all
;   1 - trace errors only
; trace_stack
;   0 - no PASE stack dump
;   1 - PASE stack dump errors only
;   2 - PASE stack dump all
; trace_break (use with trace_stack)
;   0 - PASE dspjob stack (faster, less accurate)
;   1 - PASE dbx attach stack (much slower, more accurate)
; cli api=[0,1]
;   0    - API ignore
;   1    - API trace
device_type=1
device_pid=1
trace_type=1
trace_stack=1
trace_break=1
sqloverrideccsid400=1
sqlallocenv=1
sqlallocconnect=1
sqlallochandle=1
sqlallocstmt=1
sqlbindcol=1
sqlbindfiletocol=1
sqlbindfiletoparam=1
sqlbindparam=1
sqlbindparameter=1
sqlcancel=1
sqlclosecursor=1
sqlcolattributes=1
sqlcolumnprivileges=1
sqlcolumns=1
sqlconnect=1
sqlcopydesc=1
sqldatasources=1
sqldescribecol=1
sqldescribeparam=1
sqldisconnect=1
sqldriverconnect=1
sqlendtran=1
sqlerror=1
sqlexecdirect=1
sqlexecute=1
sqlextendedfetch=1
sqlfetch=1
sqlfetchscroll=1
sqlforeignkeys=1
sqlfreeconnect=0
sqlfreeenv=0
sqlfreehandle=0
sqlfreestmt=0
sqlgetcol=1
sqlgetconnectattr=1
sqlgetconnectoption=1
sqlgetcursorname=1
sqlgetdata=1
sqlgetdescfield=1
sqlgetdescrec=1
sqlgetdiagfield=1
sqlgetdiagrec=1
sqlgetenvattr=1
sqlgetfunctions=1
sqlgetinfo=1
sqlgetlength=1
sqlgetposition=1
sqlgetstmtattr=1
sqlgetstmtoption=1
sqlgetsubstring=1
sqlgettypeinfo=1
sqllanguages=1
sqlmoreresults=1
sqlnativesql=1
sqlnextresult=1
sqlnumparams=1
sqlnumresultcols=1
sqlparamdata=1
sqlparamoptions=1
sqlprepare=1
sqlprimarykeys=1
sqlprocedurecolumns=1
sqlprocedures=1
sqlputdata=1
sqlreleaseenv=1
sqlrowcount=1
sqlsetconnectattr=1
sqlsetconnectoption=1
sqlsetcursorname=1
sqlsetdescfield=1
sqlsetdescrec=1
sqlsetenvattr=1
sqlsetparam=1
sqlsetstmtattr=1
sqlsetstmtoption=1
sqlspecialcolumns=1
sqlstarttran=1
sqlstatistics=1
sqltableprivileges=1
sqltables=1
sqltransact=1

##Recreate error##

$ cd git/ibmdb_fetchbug
$ export LIBPATH=/QOpenSys/download/trace-1.0.2-xlc
$ export PASETRACE=/QOpenSys/download/trace-1.0.2-xlc/paseclitrace.ini
$ export IBM_DB_GIL="00000000000000000000000000000000000000000000"
$ rails s -p50000
/PowerRuby/prV2R1/lib/ruby/gems/2.1.0/gems/railties-4.1.8/lib/rails/app_rails_loader.rb:37: warning: Insecure world writable dir /QOpenSys in PATH, mode 042777
/PowerRuby/prV2R1/lib/ruby/gems/2.1.0/gems/bundler-1.7.6/lib/bundler/runtime.rb:222: warning: Insecure world writable dir /QOpenSys in PATH, mode 042777
=> Booting Puma
=> Rails 4.1.8 application starting in development on http://0.0.0.0:50000
=> Run `rails server -h` for more startup options
=> Notice: server is listening on all interfaces (0.0.0.0). Consider using 127.0.0.1 (--binding option)
=> Ctrl-C to shutdown server
Puma 2.11.1 starting...
* Min threads: 0, max threads: 16
* Environment: development
* Listening on tcp://0.0.0.0:50000

<--- here is where I go to the browser and invoke a URL in the app --->

Started GET "/users/2" for 216.114.244.204 at 2015-07-07 17:38:17 +0000
   (7.6ms)  SET SCHEMA ab1_d
   (8.1ms)  SET SCHEMA ab1_d
  ActiveRecord::SchemaMigration Load (5.3ms)  SELECT schema_migrations.* FROM schema_migrations
Processing by UsersController#show as HTML
  Parameters: {"id"=>"2"}  <--- it hangs here.  

WRKACTJOB STS is THDW with the following as the last entry in the call stack:

libpthread.a(shr_xpg5 >          00000584  _event_sleep

Call stack with panic. This revealed we needed to get dbx working with 64-bit PASE.

                              Display Call Stack                             
                                                            System:   xxxxx
Job:   QP0ZSPWP       User:   QSECOFR        Number:   297055                
Thread:   00000009                                                           


Type  Program                  Statement         Procedure                   
      QP0ZPCP2   QSYS                            _CXX_PEP__Fv                
      QP0ZPCPN   QSYS          264               Qp0zNewProcess              
      QP2FORK    QSYS                            _CXX_PEP__Fv                
      QP2FORK    QSYS          16                main                        
      QP2USER2   QSYS          10                __Qp2Fork                   
      QP2USER2   QSYS          6                 runpase_main__FPi           
      QP2USER2   QSYS          5                 runpase_common__FiPvT2      
 P    dbx                              00000074  __start                     
 P    dbx                              000001C8  main                        
 P    libdbx.a(shr_64.o)               0000058C  dpi_main                    
 P    libdbx.a(shr_64.o)               000001CC  dpi_command                 
 P    libdbx.a(shr_64.o)               000000F4  process_input               
 P    libdbx.a(shr_64.o)               00000844  yyparse                     
 P    libdbx.a(shr_64.o)               00000C20  topeval    
 P    libdbx.a(shr_64.o)               0000472C  eval       
 P    libdbx.a(shr_64.o)               00000034  wherecmd   
 P    libdbx.a(shr_64.o)               00000294  walkstack  
 P    libdbx.a(shr_64.o)               000000C0  touch_sym  
 P    libdbx.a(shr_64.o)               000002CC  touch_file 
 P    libdbx.a(shr_64.o)               000009E0  readsyms   
 P    libdbx.a(shr_64.o)               00000F20  enter_nl   
 P    libdbx.a(shr_64.o)               0000081C  entersym   
 P    libdbx.a(shr_64.o)               00000488  typeName   
 P    libdbx.a(shr_64.o)               00000394  constype   
 P    libdbx.a(shr_64.o)               00000E08  constype   
 P    libdbx.a(shr_64.o)               0000019C  consRecord 
 P    libdbx.a(shr_64.o)               00000394  constype           
 P    libdbx.a(shr_64.o)               00000E50  constype           
 P    libdbx.a(shr_64.o)               00000394  constype           
 P    libdbx.a(shr_64.o)               00001470  constype           
 P    libdbx.a(shr_64.o)               000000C8  panic  <---- YIKES
 P    libdbx.a(shr_64.o)               00000068  errmsg             
 P    libc.a(shr_64.o)                 00000080  fflush             
 P    libc.a(shr_64.o)                 00000794  fflush_unlocked    
 P    libc.a(shr_64.o)                 000000BC  _xflsbuf           
 P    libc.a(shr_64.o)                 00000080  _xwrite            
 P    libc.a(shr_64.o)                 00000260  write              
 P    unix                             00000008  <syscall64>:kwrite 

Current status: Working with IBM to produce PTF for dbx

Comments (157)

  1. Former user Account Deleted

    I have lost track of release your machine, but i think please install PTF SI57578 to fix for 32bit dbx. Then we can continue with debug.

  2. Aaron Bartell reporter

    PTF SI57578 has been loaded(n1) and I am still getting the panic(n2). I've included my full PTF levels (WRKGRPPTF)(n3).

    Let me know what next steps I can take.

    (n1)

                                  Display PTF Status                              
                                                                System:   xxxxxx
    Product ID  . . . . . . . . . . . . . :   5770SS1                             
    IPL source  . . . . . . . . . . . . . :   ##MACH#B                            
    Release of base option  . . . . . . . :   V7R2M0    L00                       
    
    
    Type options, press Enter.                                                    
      5=Display PTF details   6=Print cover letter   8=Display cover letter       
      10=Display PTF apply information                                            
    
         PTF                                                   IPL                
    Opt  ID       Status                                       Action             
         TC14276  Permanently applied                          None               
         TC14101  Superseded                                   None               
         TA14276  Permanently applied                          None               
         TA14101  Superseded                                   None               
         SI57578  Temporarily applied                          None               
         SI57147  Permanently applied                          None               
         SI57146  Permanently applied                          None               
                                                                           More...
    F3=Exit   F11=Display alternate view   F17=Position to   F12=Cancel           
    

    (n2)

                                  Display Call Stack                             
                                                                System:   xxxxxx
    Job:   QP0ZSPWP       User:   QSECOFR        Number:   644963                
    Thread:   00000025                                                           
    
    
    Type  Program                  Statement         Procedure                   
          QP0ZPCP2   QSYS                            _CXX_PEP__Fv                
          QP0ZPCPN   QSYS          264               Qp0zNewProcess              
          QP2FORK    QSYS                            _CXX_PEP__Fv                
          QP2FORK    QSYS          16                main                        
          QP2USER2   QSYS          10                __Qp2Fork                   
          QP2USER2   QSYS          6                 runpase_main__FPi           
          QP2USER2   QSYS          5                 runpase_common__FiPvT2      
     P    dbx                              0000006C  __start                     
     P    dbx                              000001CC  main                        
     P    libdbx.a(shr.o)                  00000504  dpi_main                    
     P    libdbx.a(shr.o)                  000001DC  dpi_command                 
     P    libdbx.a(shr.o)                  000000F4  process_input               
     P    libdbx.a(shr.o)                  000007C8  yyparse                     
     P    libdbx.a(shr.o)                  00000C4C  topeval       
     P    libdbx.a(shr.o)                  000047E4  eval          
     P    libdbx.a(shr.o)                  00000024  wherecmd      
     P    libdbx.a(shr.o)                  0000027C  walkstack     
     P    libdbx.a(shr.o)                  000000A4  touch_sym     
     P    libdbx.a(shr.o)                  00000260  touch_file    
     P    libdbx.a(shr.o)                  00000B68  readsyms      
     P    libdbx.a(shr.o)                  00000F70  enter_nl      
     P    libdbx.a(shr.o)                  000007B8  entersym      
     P    libdbx.a(shr.o)                  00000470  typeName      
     P    libdbx.a(shr.o)                  00000364  constype      
     P    libdbx.a(shr.o)                  00000D40  constype      
     P    libdbx.a(shr.o)                  00000184  consRecord    
     P    libdbx.a(shr.o)                  00000364  constype           
     P    libdbx.a(shr.o)                  00000D88  constype           
     P    libdbx.a(shr.o)                  00000364  constype           
     P    libdbx.a(shr.o)                  000012BC  constype           
     P    libdbx.a(shr.o)                  000000C8  panic    <----------------          
     P    libdbx.a(shr.o)                  00000040  errmsg             
     P    libc.a(shr.o)                    00000080  fflush             
     P    libc.a(shr.o)                    00000784  fflush_unlocked    
     P    libc.a(shr.o)                    000000AC  _xflsbuf           
     P    libc.a(shr.o)                    00000070  _xwrite            
     P    libc.a(shr.o)                    000001A4  write              
     P    unix                             00000008  <syscall32>:kwrite 
    

    (n3)

    PTF Group             Level  Status       
    SF99776                   1  Installed    
    SF99775                   5  Installed    
    SF99769                   1  Installed    
    SF99767                   1  Installed    
    SF99766                   3  Installed    
    SF99759                   3  Related group
    SF99747                  10  Installed    
    SF99721                   3  Installed    
    SF99720               14276  Installed    
    SF99719                  26  Installed    
    SF99718                  11  Installed    
    SF99717                   1  Installed    
    SF99716                   4  Installed    
    SF99716                   6  Installed
    SF99715                   9  Installed
    SF99714                   2  Installed
    SF99713                   5  Installed
    SF99713                   9  Installed
    SF99702                   4  Installed
    SF99702                   5  Installed
    SF99481                   3  Installed
    SF99480                   3  Installed
    
  3. Former user Account Deleted

    I dunno ... check PTF was good ... $ which dbx /QOpenSys/usr/bin/dbx $ dbx /QOpenSys/usr/bin/dbx Type 'help' for help. reading symbolic information ...warning: no source compiled with -g

    HOME: No such file or directory (dbx) map

  4. Former user Account Deleted

    sorry format ...

    $ which dbx
    /QOpenSys/usr/bin/dbx
    $ dbx /QOpenSys/usr/bin/dbx
    Type 'help' for help.
    reading symbolic information ...warning: no source compiled with -g
    
    HOME: No such file or directory
    (dbx) map
    ... paste this ...
    
  5. Aaron Bartell reporter

    Here are the results:

    $ export LIBPATH=/QOpenSys/download/trace-1.0.2-xlc
    $ export PASETRACE=/QOpenSys/download/trace-1.0.2-xlc/paseclitrace.ini
    $ export IBM_DB_GIL="00000000000000000000000000000000000000000000"
    $ which dbx
    /QOpenSys/usr/bin/dbx
    $ dbx /QOpenSys/usr/bin/dbx
    Type 'help' for help.
    reading symbolic information ...warning: no source compiled with -g
    
    (dbx) map
    Entry 1:
       Object name: /QOpenSys/usr/bin/dbx
       Text origin:     0x10000000
       Text length:     0x103b5
       Data origin:     0x30000589
       Data length:     0x79f7
       File descriptor: 0x3
    
    Entry 2:
       Object name: /usr/lib/libC.a
       Member name: ansicore_32.o
       Text origin:     0xd037a600
       Text length:     0x1c500
       Data origin:     0x20560a00
       Data length:     0x842c
       File descriptor: 0x4
    
    Entry 3:
       Object name: /usr/lib/libC.a
       Member name: ansi_32.o
       Text origin:     0xd012ca00
       Text length:     0x2287f7
       Data origin:     0x20582000
       Data length:     0x36690
       File descriptor: 0x5
    
    Entry 4:
       Object name: /usr/lib/libC.a
       Member name: shrcore.o
       Text origin:     0xd0357600
       Text length:     0x22089
       Data origin:     0x2055bc00
       Data length:     0x3e58
       File descriptor: 0x6
    
    Entry 5:
       Object name: /usr/lib/libcdebug.a
       Member name: shr.o
       Text origin:     0xd1b10100
       Text length:     0xc4ec
       Data origin:     0x20691b10
       Data length:     0xff4
       File descriptor: 0x7
    
    Entry 6:
       Object name: /usr/lib/libdbx.a
       Member name: coredebug.o
       Text origin:     0xd1d94e80
       Text length:     0x1addd
       Data origin:     0x2068ed28
       Data length:     0x16d8
       File descriptor: 0x8
    
    Entry 7:
       Object name: /usr/lib/libpthdebug.a
       Member name: shr.o
       Text origin:     0xd1d1c100
       Text length:     0x77216
       Data origin:     0x205bf188
       Data length:     0xce428
       File descriptor: 0x9
    
    Entry 8:
       Object name: /usr/lib/libdbx.a
       Member name: stackdebug.o
       Text origin:     0xd1af1ca0
       Text length:     0x1df00
       Data origin:     0x205bc790
       Data length:     0x1d40
       File descriptor: 0xa
    
    Entry 9:
       Object name: /usr/lib/libdbx.a
       Member name: procdebug.o
       Text origin:     0xd1ad4080
       Text length:     0x1c185
       Data origin:     0x205b9800
       Data length:     0x1ff0
       File descriptor: 0xb
    
    Entry 10:
       Object name: /usr/lib/libiconv.a
       Member name: shr4.o
       Text origin:     0xd04e3100
       Text length:     0x26489
       Data origin:     0x2056dd80
       Data length:     0x13f2c
       File descriptor: 0xc
    
    Entry 11:
       Object name: /usr/lib/libC.a
       Member name: shr.o
       Text origin:     0xd010c100
       Text length:     0x1fed6
       Data origin:     0x20569d00
       Data length:     0x30f0
       File descriptor: 0xd
    
    Entry 12:
       Object name: /usr/lib/libdecNumber.a
       Member name: shr.o
       Text origin:     0xd12de100
       Text length:     0x15b4e
       Data origin:     0x20558080
       Data length:     0x2b68
       File descriptor: 0xe
    
    Entry 13:
       Object name: /usr/lib/libpthreads.a
       Member name: shr_comm.o
       Text origin:     0x20434000
       Text length:     0x315f
       Data origin:     0x20510000
       Data length:     0x43920
       File descriptor: 0xf
    
    Entry 14:
       Object name: /usr/lib/libcrypt.a
       Member name: shr.o
       Text origin:     0xd0356100
       Text length:     0x9be
       Data origin:     0x2050f6a8
       Data length:     0x120
       File descriptor: 0x10
    
    Entry 15:
       Object name: /usr/lib/libdbx.a
       Member name: shr.o
       Text origin:     0xd1b37100
       Text length:     0x1e4a09
       Data origin:     0x20693d00
       Data length:     0x1cc170
       File descriptor: 0x11
    
    Entry 16:
       Object name: /usr/lib/libpthreads.a
       Member name: shr_xpg5.o
       Text origin:     0x203f4000
       Text length:     0x3f14d
       Data origin:     0x20554000
       Data length:     0x3f8c
       File descriptor: 0x12
    
    Entry 17:
       Object name: /usr/lib/libc.a
       Member name: shr.o
       Text origin:     0x20000000
       Text length:     0x3f3191
       Data origin:     0x20438350
       Data length:     0xd6810
       File descriptor: 0x13
    
  6. Former user Account Deleted

    Well, looks correct (32-bit) ... but why dbx not work with whatever Ruby you are using???

    bash-4.3$ which ruby
    /usr/bin/ruby
    bash-4.3$ dbx /usr/bin/ruby
    Type 'help' for help.
    reading symbolic information ...dbx: fatal error: nesting depth limit (25) exceeded.
    Use the -d option to increase nesting depth limit.
    bash-4.3$ dbx -d 100 /usr/bin/ruby
    Type 'help' for help.
    reading symbolic information ...internal error: assertion failed at line 5562 in file object.c
    ... errors ...
    (dbx) where
    __start() at 0x10000150
    (dbx) map
    Entry 1:
       Object name: /usr/bin/ruby
       Text origin:     0x10000000
    
  7. Aaron Bartell reporter

    Here are the results. Could you run which ruby | xargs ls -all so we can see which version you are pointing at? Mine is pointing at prV2R1, as shown below.

    $ which ruby | xargs ls -all
    lrwxrwxrwx    1 aaron    0                68 May 22 21:18 /QOpenSys/usr/bin/ruby -> ../../../PowerRuby/prV2R1/bin/ruby
    $ dbx /QOpenSys/usr/bin/ruby
    Type 'help' for help.
    reading symbolic information ...dbx: fatal error: nesting depth limit (25) exceeded.
    Use the -d option to increase nesting depth limit.
    $ dbx -d 100 /QOpenSys/usr/bin/ruby
    Type 'help' for help.
    reading symbolic information ...internal error: assertion failed at line 5562 in file object.c
    internal error: assertion failed at line 5562 in file object.c
    .... same error many times ....
    internal error: assertion failed at line 5562 in file object.c
    
    (dbx) where
    __start() at 0x10000150
    (dbx) map
    Entry 1:
       Object name: /QOpenSys/usr/bin/ruby
       Text origin:     0x10000000
       Text length:     0x33ebe9
       Data origin:     0x20558adc
       Data length:     0x3e650
       File descriptor: 0x3
    
    Entry 2:
       Object name: /usr/lib/librtl.a
       Member name: shr.o
       Text origin:     0xd0564b80
       Text length:     0x2f6
       Data origin:     0xf010cd80
       Data length:     0x7c
       File descriptor: 0x4
    
    Entry 3:
       Object name: /usr/lib/libc.a
       Member name: shr.o
       Text origin:     0x20044000
       Text length:     0x3f3191
       Data origin:     0x20438350
       Data length:     0xd6810
       File descriptor: 0x5
    
    Entry 4:
       Object name: /usr/lib/libcrypt.a
       Member name: shr.o
       Text origin:     0xd0356100
       Text length:     0x9be
       Data origin:     0x2050f6a8
       Data length:     0x120
       File descriptor: 0x6
    
    Entry 5:
       Object name: /usr/lib/libpthread.a
       Member name: shr_xpg5.o
       Text origin:     0x20004000
       Text length:     0x3f14d
       Data origin:     0x20554000
       Data length:     0x3f8c
       File descriptor: 0x7
    
    Entry 6:
       Object name: /usr/lib/libpthread.a
       Member name: shr_comm.o
       Text origin:     0x20000000
       Text length:     0x315f
       Data origin:     0x20510000
       Data length:     0x43920
       File descriptor: 0x8
    
  8. Former user Account Deleted

    Well, answer V2R0, but slightly irrelevant (truthfully). I much more interested in a strategy of debug where YOU (not me), can be self helping, aka, libdb400.a trace tool 'works for anybody'. So, while DB2 problem itself is nasty, it is also the perfect sort of issue to work out the tools (ie, 'what the blue blazing saddles is going on' --- perfect problem)

    (dbx) quit
    bash-4.3$ which ruby | xargs ls -all
    lrwxrwxrwx    1 adc      0                52 Mar 31 12:18 /usr/bin/ruby -> /PowerRuby/prV2R0/bin/ruby
    b
    
  9. Former user Account Deleted

    So, next, i would like your to dbx attach to a running Ruby application ...

    > ruby my_problem_app
    > ps
    > 12345 ruby
    > dbx -d 100 -a 12345
    > where
    
  10. Former user Account Deleted

    Well belive it or not, that was ok ... but do it again, and, run where twice ...

    > ruby my_problem_app
    > ps
    > 12345 ruby
    > dbx -d 100 -a 12345
    dbx> where
    ** ton o errors ***
    dbx> where 
    -- should look ok, paste here --
    
  11. Aaron Bartell reporter

    Here is the second where...

    (dbx) where
    _event_sleep(??, ??, ??, ??, ??, ??) at 0x2001a4d4
    _event_wait(??, ??) at 0x2001b1cc
    _cond_wait_local(??, ??, ??) at 0x20029130
    _cond_wait(??, ??, ??) at 0x200298c4
    pthread_cond_timedwait(??, ??, ??) at 0x2002a1cc
    unnamed block in native_sleep(th = 0x242e55b0, timeout_tv = 0x243e9f1c), line 1371 in "thread_pthread.c"
    unnamed block in native_sleep(th = 0x242e55b0, timeout_tv = 0x243e9f1c), line 1371 in "thread_pthread.c"
    unnamed block in native_sleep(th = 0x242e55b0, timeout_tv = 0x243e9f1c), line 1371 in "thread_pthread.c"
    native_sleep(th = 0x242e55b0, timeout_tv = 0x243e9f1c), line 1371 in "thread_pthread.c"
    sleep_timeval.constprop.52(th = 0x242e55b0, tv = (...)), line 1049 in "thread.c"
    rb_f_sleep(argc = 1, argv = 0x242e79a4), line 4230 in "process.c"
    call_cfunc_m1(func = ??, recv = ??, argc = ??, argv = ??), line 1317 in "vm_insnhelper.c"
    vm_call_cfunc_with_frame(th = 0x242e55b0, reg_cfp = 0x24367940, ci = ??), line 1489 in "vm_eval.c"
    unnamed block in vm_exec_core(th = ??, initial = ??), line 1073 in "vm_eval.c"
    unnamed block in vm_exec_core(th = ??, initial = ??), line 1073 in "vm_eval.c"
    vm_exec_core(th = ??, initial = ??), line 1073 in "vm_eval.c"
    unnamed block in vm_exec(th = 0x242e55b0), line 1398 in "vm_eval.c"
    vm_exec(th = 0x242e55b0), line 1398 in "vm_eval.c"
    unnamed block in invoke_block_from_c(th = 0x242e55b0, block = 0x24367a90, self = 605910520, argc = 0, argv = ??, blockptr = ??, cref = (nil), defined_class = ??), line 817 in "vm_eval.c"
    invoke_block_from_c(th = 0x242e55b0, block = 0x24367a90, self = 605910520, argc = 0, argv = ??, blockptr = ??, cref = (nil), defined_class = ??), line 817 in "vm_eval.c"
    unnamed block in vm_invoke_proc(th = 0x242e55b0, proc = 0x24367a90, self = 605910520, defined_class = 564888580, argc = 0, argv = 0x241d75c4, blockptr = (nil)), line 881 in "vm_eval.c"
    vm_invoke_proc(th = 0x242e55b0, proc = 0x24367a90, self = 605910520, defined_class = 564888580, argc = 0, argv = 0x241d75c4, blockptr = (nil)), line 881 in "vm_eval.c"
    unnamed block in thread_start_func_2(th = 0x242e55b0, stack_start = 0x243ea000), line 535 in "thread.c"
    thread_start_func_2(th = 0x242e55b0, stack_start = 0x243ea000), line 535 in "thread.c"
    thread_start_func_1(th_ptr = 0x242e55b0), line 803 in "thread_pthread.c"
    
  12. Former user Account Deleted

    Ok, i am greatly confused, dbx attach just worked fine. But when you try libdb400.a stack, it blows up???

    Is this correct?

  13. Aaron Bartell reporter

    Ok, I am going to lay out two scenarios in full. The first is using dbx "inline" (i.e. I don't manually invoke it in the shell and instead paseclitrace does.)

    #Scenario 1

    $ cd git/ibmdb_fetchbug/
    $ export LIBPATH=/QOpenSys/download/trace-1.0.2-xlc
    $ export PASETRACE=/QOpenSys/download/trace-1.0.2-xlc/paseclitrace.ini
    $ export IBM_DB_GIL="00000000000000000000000000000000000000000000"
    $ rails s -p50000
    => Booting Puma
    => Rails 4.1.8 application starting in development on http://0.0.0.0:50000
    => Run `rails server -h` for more startup options
    => Notice: server is listening on all interfaces (0.0.0.0). Consider using 127.0.0.1 (--binding option)
    => Ctrl-C to shutdown server
    Puma 2.11.1 starting...
    * Min threads: 0, max threads: 16
    * Environment: development
    * Listening on tcp://0.0.0.0:50000
    

    At this point I load a page in browser and it remains waiting for a response. Below are the call stacks for the dbx and ruby jobs. I waited for at least 15 minutes with no response. Note there isn't a panic in the dbx job like before. I am not sure why panic isn't there anymore. As best I can tell I did everything the same as this morning.

    dbx job (not initiated by manual attachment via pid):

                                  Display Call Stack                               
                                                                System:   xxxx
    Job:   QP0ZSPWP       User:   QSECOFR        Number:   658889                  
    Thread:   000003FE                                                             
    
    
    Type  Program                  Statement         Procedure                     
          QP0ZPCP2   QSYS                            _CXX_PEP__Fv                  
          QP0ZPCPN   QSYS          264               Qp0zNewProcess                
          QP2FORK    QSYS                            _CXX_PEP__Fv                  
          QP2FORK    QSYS          16                main                          
          QP2USER2   QSYS          10                __Qp2Fork                     
          QP2USER2   QSYS          6                 runpase_main__FPi             
          QP2USER2   QSYS          5                 runpase_common__FiPvT2        
     P    dbx                              0000006C  __start                       
     P    dbx                              000001CC  main                          
     P    libdbx.a(shr.o)                  00000504  dpi_main                      
     P    libdbx.a(shr.o)                  000001DC  dpi_command                   
     P    libdbx.a(shr.o)                  000000F4  process_input                 
     P    libdbx.a(shr.o)                  000007C8  yyparse                       
     P    libdbx.a(shr.o)                  00000C4C  topeval          
     P    libdbx.a(shr.o)                  000047E4  eval             
     P    libdbx.a(shr.o)                  00000024  wherecmd         
     P    libdbx.a(shr.o)                  0000028C  walkstack        
     P    libdbx.a(shr.o)                  000000B0  printfullcallinfo
     P    libdbx.a(shr.o)                  00000204  printcallinfo    
     P    libdbx.a(shr.o)                  000001A4  printparams      
     P    libdbx.a(shr.o)                  000002D4  printparamv      
     P    libdbx.a(shr.o)                  0000069C  printv           
     P    libdbx.a(shr.o)                  00000310  printval         
     P    libdbx.a(shr.o)                  000009C8  c_printval       
     P    libc.a(shr.o)                    000000E4  fprintf          
     P    libc.a(shr.o)                    00001E74  _doprnt          
     P    libc.a(shr.o)                    000000B8  fwrite@AF5_4      
     P    libc.a(shr.o)                    00000184  fwrite_unlocked   
     P    libc.a(shr.o)                    000000AC  _xflsbuf          
     P    libc.a(shr.o)                    00000070  _xwrite           
     P    libc.a(shr.o)                    000001A4  write             
     P    unix                             00000008  <syscall32>:kwrite
    

    Ruby job with Rails server:

                                  Display Call Stack                             
                                                                System:   xxxx
    Job:   QP0ZSPWP       User:   QSECOFR        Number:   658887                
    Thread:   000001DD                                                           
    
    
    Type  Program                  Statement         Procedure                   
          QP0ZPCP2   QSYS                            _CXX_PEP__Fv                
          QP0ZPCPN   QSYS          264               Qp0zNewProcess              
          QP2FORK    QSYS                            _CXX_PEP__Fv                
          QP2FORK    QSYS          16                main                        
          QP2USER2   QSYS          10                __Qp2Fork                   
          QP2USER2   QSYS          6                 runpase_main__FPi           
          QP2USER2   QSYS          5                 runpase_common__FiPvT2      
     P    ruby                             0000006C  __start                     
     P    ruby                     36      00000064  main                        
     P    ruby                     318     00000074  ruby_run_node               
     P    ruby                     253     000000E4  ruby_exec_internal          
     P    ruby                             00000148  rb_iseq_eval_main           
     P    ruby                             000000AC  vm_exec                     
     P    ruby                             000012F8  vm_exec_core               
     P    ruby                             000001E0  vm_call_method             
     P    ruby                             00000138  vm_call_cfunc_with_frame   
     P    ruby                             00000030  call_cfunc_1               
     P    ruby                     1587    0000070C  rb_require_safe            
     P    ruby                     615     00000164  rb_load_internal0          
     P    ruby                             00000138  rb_iseq_eval               
     P    ruby                             000000AC  vm_exec                    
     P    ruby                             00001690  vm_exec_core               
     P    ruby                             000001E0  vm_call_method             
     P    ruby                             00000138  vm_call_cfunc_with_frame   
     P    ruby                             0000002C  call_cfunc_0               
     P    ruby                             00000018  rb_obj_tap                 
     P    ruby                             00000074  rb_yield                   
     P    ruby                             00000BC0  invoke_block_from_c        
     P    ruby                             000000AC  vm_exec                    
     P    ruby                             000012F8  vm_exec_core               
     P    ruby                             000001E0  vm_call_method             
     P    ruby                             00000138  vm_call_cfunc_with_frame   
     P    ruby                             00000038  call_cfunc_m1              
     P    ruby                             00000120  thread_join_m              
     P    ruby                     853     000000F0  rb_ensure                  
     P    ruby                             00000118  thread_join_sleep          
     P    ruby                             000000D4  native_sleep.constprop.56  
     P    libpthread.a(shr_xpg5 >          000001A0  pthread_cond_wait          
     P    libpthread.a(shr_xpg5 >          000000C8  _cond_wait                 
     P    libpthread.a(shr_xpg5 >          000004FC  _cond_wait_local 
     P    libpthread.a(shr_xpg5 >          00000350  _event_wait      
     P+                                                               
     P+   libpthread.a(shr_xpg5 >          00000584  _event_sleep     
     P    libpthread.a(shr_xpg5 >          00000584  _event_sleep     
    

    Convey libdb400* files from /tmp/ via cat:

     $ ls -all /tmp/
     total 760
     drwxrwsrwt    7 qsys     0             36864 Aug 18 21:48 .
     drwxrwsrwx   24 qsys     0            241664 Jun  5 16:59 ..
     drwxrwxrwt    5 aaron    0              8192 Aug 18 01:25 .com_ibm_tools_attach
     drwxrwsrwx    2 qsecofr  0              8192 Jun  5 14:17 ZendCoreMySql
     -rwxrwxrwx    1 qsecofr  0               770 Jun  5 14:16 ZendServerInstall.log
     drwxrwsrwx    2 qbrms    0              8192 May 21 22:52 brms
     -rw-r--r--    1 aaron    0                19 Aug 18 21:31 libdb400_trace_cmd1_89956
     -rw-r--r--    1 aaron    0               432 Aug 18 21:31 libdb400_trace_cmd2_89956
     -rwxrwxrwx    1 qsys     0              3372 May 21 22:52 lprcume.log
     -rwxrwxrwx    1 qsys     0              2843 May 21 22:37 lpume.log
     -rw-r--r--    1 qsecofr  0                 3 Aug  8 00:13 sshd.pid
     $ cat /tmp/libdb400_trace_cmd1_89956
     thread
     detach
     quit
     $ cat /tmp/libdb400_trace_cmd2_89956
     print "---------thread 1-----------"
     thread current 1
     where
     print "---------thread 2-----------"
     thread current 2
     where
     print "---------thread 3-----------"
     thread current 3
     where
     print "---------thread 4-----------"
     thread current 4
     where
     print "---------thread 5-----------"
     thread current 5
     where
     print "---------thread 6-----------"
     thread current 6
     where
     print "---------thread 7-----------"
     thread current 7
     where
     detach
     quit
    

    # Scenario 2 ##Shell session 1 Note I do not use the paseclitrace in this scenario. Should I be using it? Note I tried this scenario with paseclitrace but it didn't produce anything in /tmp.

    $ cd git/ibmdb_fetchbug/
    $ rails s -p50000
    => Booting Puma
    => Rails 4.1.8 application starting in development on http://0.0.0.0:50000
    => Run `rails server -h` for more startup options
    => Notice: server is listening on all interfaces (0.0.0.0). Consider using 127.0.0.1 (--binding option)
    => Ctrl-C to shutdown server
    Puma 2.11.1 starting...
    * Min threads: 0, max threads: 16
    * Environment: development
    * Listening on tcp://0.0.0.0:50000
    

    ##Shell session 2

    $ ps -U aaron
          UID   PID    TTY  TIME CMD
          111 76001  pts/1  0:00 bash
          111 89984  pts/0  0:00 bash
          111 89987  pts/2  0:00 bash
          111 89992  pts/3  0:00 bash
          111 89994  pts/0  0:02 ruby
          111 89995  pts/2  0:00 ps
    $ dbx -d 100 -a 89994
    Waiting to attach to process 89994 ...
    Successfully attached to /PowerRuby/prV2R1/bin/ruby.
    Type 'help' for help.
    reading symbolic information ...internal error: assertion failed at line 5562 in file object.c
    internal error: assertion failed at line 5562 in file object.c
    ... same error repeated ...
    internal error: assertion failed at line 5562 in file object.c
    
    stopped in _event_sleep at 0x2001a6e4 ($t7)
    0x2001a6e4 (_event_sleep+0x584) 80410014         lwz   r2,0x14(r1)
    (dbx)
    

    dbx job (initiated manually as shown above):

                                  Display Call Stack                               
                                                                System:   xxxx  
    Job:   QP0ZSPWP       User:   QSECOFR        Number:   658926                  
    Thread:   00000401                                                             
    
    
    Type  Program                  Statement         Procedure                     
          QP0ZPCP2   QSYS                            _CXX_PEP__Fv                  
          QP0ZPCPN   QSYS          264               Qp0zNewProcess                
          QP2FORK    QSYS                            _CXX_PEP__Fv                  
          QP2FORK    QSYS          16                main                          
          QP2USER2   QSYS          10                __Qp2Fork                     
          QP2USER2   QSYS          6                 runpase_main__FPi             
          QP2USER2   QSYS          5                 runpase_common__FiPvT2        
     P    dbx                              0000006C  __start                       
     P    dbx                              000002A0  main                          
     P    dbx                              00000238  getline                       
     P    dbx                              000001E8  io_readbuff                   
     P    libc.a(shr.o)                    0000028C  read                          
     P    unix                             00000008  <syscall32>:kread             
                                                                            Bottom 
    

    Ruby job with Rails server:

                                  Display Call Stack                             
                                                                System:   xxxx
    Job:   QP0ZSPWP       User:   QSECOFR        Number:   658921                
    Thread:   000001E4                                                           
    
    
    Type  Program                  Statement         Procedure                   
          QP0ZPCP2   QSYS                            _CXX_PEP__Fv                
          QP0ZPCPN   QSYS          264               Qp0zNewProcess              
          QP2FORK    QSYS                            _CXX_PEP__Fv                
          QP2FORK    QSYS          16                main                        
          QP2USER2   QSYS          10                __Qp2Fork                   
          QP2USER2   QSYS          6                 runpase_main__FPi           
          QP2USER2   QSYS          5                 runpase_common__FiPvT2      
     P    ruby                             0000006C  __start                     
     P    ruby                     36      00000064  main                        
     P    ruby                     318     00000074  ruby_run_node               
     P    ruby                     253     000000E4  ruby_exec_internal          
     P    ruby                             00000148  rb_iseq_eval_main           
     P    ruby                             000000AC  vm_exec                     
     P    ruby                             000012F8  vm_exec_core            
     P    ruby                             000001E0  vm_call_method          
     P    ruby                             00000138  vm_call_cfunc_with_frame
     P    ruby                             00000030  call_cfunc_1            
     P    ruby                     1587    0000070C  rb_require_safe         
     P    ruby                     615     00000164  rb_load_internal0       
     P    ruby                             00000138  rb_iseq_eval            
     P    ruby                             000000AC  vm_exec                 
     P    ruby                             00001690  vm_exec_core            
     P    ruby                             000001E0  vm_call_method          
     P    ruby                             00000138  vm_call_cfunc_with_frame
     P    ruby                             0000002C  call_cfunc_0            
     P    ruby                             00000018  rb_obj_tap              
     P    ruby                             00000074  rb_yield                  
     P    ruby                             00000BC0  invoke_block_from_c       
     P    ruby                             000000AC  vm_exec                   
     P    ruby                             000012F8  vm_exec_core              
     P    ruby                             000001E0  vm_call_method            
     P    ruby                             00000138  vm_call_cfunc_with_frame  
     P    ruby                             00000038  call_cfunc_m1             
     P    ruby                             00000120  thread_join_m             
     P    ruby                     853     000000F0  rb_ensure                 
     P    ruby                             00000118  thread_join_sleep         
     P    ruby                             000000D4  native_sleep.constprop.56 
     P    libpthread.a(shr_xpg5 >          000001A0  pthread_cond_wait         
     P    libpthread.a(shr_xpg5 >          000000C8  _cond_wait                
     P    libpthread.a(shr_xpg5 >          000004FC  _cond_wait_local         
     P    libpthread.a(shr_xpg5 >          00000350  _event_wait              
     P    libpthread.a(shr_xpg5 >          00000584  _event_sleep             
     P    unix                             00000008  <syscall32>:thread_tsleep
    

    In summary, the panic is gone but it is still hanging.

  14. Former user Account Deleted

    Anyway, panic aside, dbx attach is slow, so thinking removing dbx and dumping stack from within libdb400.a trace module ... but not tonight ... I will think design over this evening.

  15. Former user Account Deleted

    It will look something like this ...

    #include <pthread.h>
    #include <stdio.h>
    #include <stdlib.h>
    #include <unistd.h>
    #include <string.h>
    
    #define uint16 unsigned short
    #define uint32 unsigned int
    #define Address unsigned int
    
    typedef struct FN_NAME
    {
        uint16 nameLen;
        char name[1];
    };
    typedef struct tbtable_short
    {
        uint32 zeroAnchor;      /* include this in to make things simpler */
        uint32 version:8;       /* traceback format version               */
        uint32 lang:8;          /* See language values below              */
        uint32 globallink:1;    /* Set if routine is global linkage       */
        uint32 is_eprol:1;      /* Set if is out-of-line epilog/prologue  */
        uint32 has_tboff:1;     /* Set if offset from start of proc stored */
        uint32 int_proc:1;      /* Set if routine is internal         */
        uint32 has_ctl:1;       /* Set if routine involves controlled storage */
        uint32 tocless:1;       /* Set if routine contains no TOC     */
        uint32 fp_present:1;    /* Set if routine performs FP operations  */
        uint32 log_abort:1;     /* Set if routine logs or aborts FP ops   */
        uint32 int_hndl:1;      /* Set if routine is interrupt handler    */
        uint32 name_present:1;  /* Set if name is present in proc table */
        uint32 uses_alloca:1;   /* Set if alloca used to allocate storage */
        uint32 cl_dis_inv:3;    /* On-condition directives, see below */
        uint32 saves_cr:1;      /* Set if procedure saves the condition reg */
        uint32 saves_lr:1;      /* Set if procedure saves the link reg */
        uint32 stores_bc:1;     /* Set if procedure stores the backchain */
        uint32 fixup:1;         /* Set if code is generated fixup code. */
        uint32 fpr_saved:6;     /* Number of FPRs saved, max of 32 */
        uint32 spare3:2;        /* Spare bits */
        uint32 gpr_saved:6;     /* Number of GPRs saved, max of 32 */
        uint32 fixedparms:8;    /* Number of fixed point parameters */
        uint32 floatparms:7;    /* Number of floating point parameters */
        uint32 parmsonstk:1;    /* Set if all parameters placed on stack */
    };
    
    
    typedef struct TiaStackFrame32 {
      uint32 backChain;
      uint32 savedCR;
      uint32 savedLR;
      uint32 resrv1;
      uint32 resrv2;
      uint32 toc;
      uint32 parmRegs[8];
      uint32 pad[2];
    };
    
    /*
    typedef struct TiaStackFrame64 {
      uint64 backChain;
      uint32 savedCR;
      uint32 resvd;
      uint64 savedLR;
      uint64 resrv1;
      uint64 resrv2;
      uint64 toc;
      uint64 parmRegs[8];
    };
    */
    
    Address pase_GPR1();
    #pragma mc_func pase_GPR1 { "38610000" }
    
    
    void fred_de_very_long_name_heh_what_could_this_possibly_be_when_off_the_end() {
      Address stk = pase_GPR1();
      Address backchain;
      Address goforth;
      struct TiaStackFrame32 *frame;
      struct tbtable_short *tb;
      enum { FNOFFSET_INVALID = -1 }; // any odd number would do
      while (stk) {
        frame = (struct TiaStackFrame32 *) stk;
        printf("%p = %p %p %p %p %p %p %p %p %p %p %p %p\n",stk,
        frame->backChain,
        frame->savedCR,
        frame->savedLR,
        frame->toc,
        frame->parmRegs[0],
        frame->parmRegs[1],
        frame->parmRegs[2],
        frame->parmRegs[3],
        frame->parmRegs[4],
        frame->parmRegs[5],
        frame->parmRegs[6],
        frame->parmRegs[7]
        );
        backchain = *(Address *)stk;
        /* looking for zero word tbtable start */
        goforth = frame->savedLR;
        printf("lr %p\n",goforth);
        while (*(Address *)goforth) {
          goforth += sizeof(uint32);
        }
        tb = (struct tbtable_short *) goforth;
        printf("goforth %p version %d present %d gprs %d\n",goforth, tb->version, tb->name_present, tb->gpr_saved);
        if (tb->name_present) {
          Address nameOffset;
          Address fnOffset;
          uint32 numCtl;
          struct FN_NAME *fn;
          uint32 tb_len = 256;
    
          nameOffset = sizeof(*tb);
          if ((tb->fixedparms + tb->floatparms) > 0) nameOffset += sizeof(uint32);
          fnOffset = FNOFFSET_INVALID;
          if (tb->has_tboff) {
            fnOffset = *(uint32*)((char*)tb + nameOffset);
            nameOffset += sizeof(uint32);
          }
          if (tb->int_hndl) nameOffset += sizeof(uint32);
          if (tb->has_ctl) {
            numCtl = *(uint32*)((char*)tb + nameOffset);
            nameOffset += (sizeof(numCtl) + (numCtl * sizeof(uint32)));
          }
          if (nameOffset < (tb_len - sizeof(uint16)))
          {
            fn = (struct FN_NAME*)((char*)tb + nameOffset);
            if (fn->nameLen && ((nameOffset + fn->nameLen) <= (tb_len - sizeof(uint16))))
            {
              printf("%s\n",fn->name);
            }
          }
        }
        /* printf("%p %p\n",stk, backchain); */
        stk = backchain;
      } /* while backchain */
    }
    int main(int argc, char * argv[]) {
      fred_de_very_long_name_heh_what_could_this_possibly_be_when_off_the_end();
      return 0;
    }
    
  16. Former user Account Deleted

    run within libdb400.a of course ... but ... this sort of stuff (format pretty) ...

    bash-4.3$ stackme
    2ff22bc0 = 2ff22c60 0 0 0 f016c814 f016c804 2ff22c30 0 d0175968 0 0 f01757d0
    lr 10000418
    goforth 100005dc version 0 present 1 gprs 5
    fred_de_very_long_name_heh_what_could_this_possibly_be_when_off_the_end
    2ff22c60 = 2ff22ca0 0 10000658 deadbeef deadbeef deadbeef deadbeef deadbeef deadbeef a f010cb70 d010cd80
    lr 10000658
    goforth 1000066c version 0 present 1 gprs 0
    main
    2ff22ca0 = 0 20000000 10000194 2000085c 1 2ff22d28 0 0 0 0 0 0
    lr 10000194
    goforth 100001b4 version 0 present 1 gprs 0
    __start
    
  17. Former user Account Deleted

    Ok a new "super fast" internal stack dump available for libdb400.a trace version.

    Yips Service (see CLI trace)

    ; device_type=[tty,file]
    ;   0  - console
    ;   1  - file (/tmp/libdb400_trace)
    ; device_pid (device_type=1-file)
    ;   0 - /tmp/libdb400_trace
    ;   1 - /tmp/libdb400_trace[_pid]
    ; trace_type
    ;   0 - trace all
    ;   1 - trace errors only
    ; trace_stack
    ;   0 - no PASE stack dump
    ;   1 - PASE stack dump errors only
    ;   2 - PASE stack dump all
    ; trace_break (use with trace_stack)
    ;   0 - PASE internal stack (very fast, internal, recommended)
    ;   1 - PASE dspjob stack (slower, external, not recommended)
    ;   2 - PASE dbx attach stack (much slower, external, not recommended)
    ; cli api=[0,1]
    ;   0    - API ignore
    ;   1    - API trace
    
  18. Aaron Bartell reporter

    I have loaded 1.0.3 of the cli trace tool and left the paseclitrace.ini file as it was in the zip.

    Steps to run:

    export LIBPATH=/QOpenSys/download/trace-1.0.3-xlc
    export PASETRACE=/QOpenSys/download/trace-1.0.3-xlc/paseclitrace.ini
    export IBM_DB_GIL="00000000000000000000000000000000000000000000"
    
    rails s -p50000
    

    Then i go to browser and refresh until error occurs.

    Here is the trace log after producing the error.

  19. Former user Account Deleted

    We see and error ... SQL_INVALID_HANDLE. However with trace function only tracing errors, we can not see anything leading up to the invalid handle. Aka, speculation, could simply have been closed, possibly application and/or ibm_db, but we do not have data. Try paseclitrace.ini more data (trace_type=0, trace_stack=1, trace_break=0).

    BTW -- SQLGetData as SQL_SUCCESS_WITH_INFO 1 is ok (need change trace function).

    SQLNumResultCols.176822.24003072.retn SQLRETURN sqlrc 0xfffffffe (-2)
    
  20. Former user Account Deleted

    Sorry, i mean try paseclitrace.ini more data (trace_type=0, trace_stack=2, trace_break=0) ... trace everything with stack dump.

  21. Aaron Bartell reporter

    When I set trace_stack=2 I get a core dump/seg-fault from Ruby the first time I hit the URL, so I am not even getting to the column metadata error at this point. If I set trace_stack=1 then it doesn't core dump. Here is the pid trace log, though it shows no errors.

    Here is what I have /QOpenSys/download/trace-1.0.3-xlc/paseclitrace.ini set to:

    device_type=1
    device_pid=1
    trace_type=0
    trace_stack=2
    trace_break=0
    
  22. Former user Account Deleted

    Well, as you can see the Ruby "core dump" is useless (not intended to start debate). Therefore, we need to see PASE core dump ... STRSST ... look for 4700 0012 (around time failure).

    We need to understand if tooling is dead (needs fix), or, we have started the hounds barking on the real issue.

    BTW -- yes, this is taking time, but developing a good tool to save time later (many times), takes some real world bump and retry work. IF i had enough time i could do this all my self, but, well, just not the case.

  23. Aaron Bartell reporter

    It's been incredibly long since I've done STRSST so I will need some guidance. Should I be using the YiPs PASEDebug page for a start? Specifically, the section labeled Part 1 — Obvious answer, job ended normally?

  24. Former user Account Deleted

    Wrong section ... VLOGs are not real-time "trace", but post death artifact, thereby, a VLOG "record" 4700 0012 is "added" any time PASE takes a "coredump" (any PASE application).

    PASE understand VLOGS 4700 0012 (green screen STRSST/STRDST)
    You machine has dead PASE
    
    When PASE is guilty of dying then often times you will find static data in the VLOGS.
    
    STRSST/STRDST
    1. Start a service tool
    5. Licensed Internal Code log
    1. Select entries from the Licensed Internal Code (LIC) log
    [@
    Just press enter ...
    
     Type choices, press Enter.
    
       Entry ID:
         Starting  . . . . . . . . . . .   FFFFFFFF   00000000-FFFFFFFF
    
    … default options until you see list of vlogs …
    
        > 0100642A  OS/400 PASE              4700  0100  07/21/11  14:55:15      9
        > 0100642A  OS/400 PASE              4700  0012  07/21/11  14:55:15      9
        > 0100642B  OS/400 PASE              4700  0013  07/21/11  14:55:17      9
    
        Looking for ...
        4700 0100 - PASE panic (all of pase dies)
        4700 0012 - PASE core dump (pase process dies)
    
  25. Aaron Bartell reporter

    Followed your instructions. Not seeing the PASE panic. Note: I received a core dump of the Ruby runtime before I obtained the ibm_db error, so I am not sure if the below is from the core dump or from the ibm_db error. I am guessing it is from the core dump. Note the ibm_db fetch error does NOT core dump and is instead caught and conveys a message back to the browser.

    See below for the IBM i PASE entry that this spool file data represents.

                    Select Entries from Licensed Internal Code Log                
    
    Type options, press Enter to dump entry to selected device.                   
      1=Printer   2=Media   5=Display entry   8=Display note                      
    
         Entry     Major                    Major Minor                     Dump  
    Opt  ID        Description              Code  Code  Date      Time     K bytes
         0100092B  DASD support             3300  5019  08/30/15  05:12:42      1 
         0100092C  DASD support             3300  5019  08/30/15  06:13:27      1 
         0100092D  DASD support             3300  5019  08/30/15  06:13:29      1 
         0100092E  DASD support             3300  5019  08/30/15  06:13:29      1 
         0100092F  DASD support             3300  5019  08/30/15  06:13:31      1 
         01000930  DASD support             3300  5019  08/31/15  05:11:57      1 
         01000931  DASD support             3300  5019  08/31/15  05:11:57      1 
         01000932  DASD support             3300  5019  08/31/15  05:11:57      1 
         01000933  DASD support             3300  5019  08/31/15  05:11:57      1 
         01000934  DASD support             3300  5019  08/31/15  06:11:58      1 
         01000935  DASD support             3300  5019  08/31/15  06:11:58      1 
         01000936  DASD support             3300  5019  08/31/15  06:11:58      1 
         01000937  DASD support             3300  5019  08/31/15  06:11:58      1 
       > 01000938  IBM i PASE               4700  0012  08/31/15  14:31:30     15 
                                                                            Bottom
    

    Observation: I am seeing entries for /usr/lib/libssl.a. I know that PowerRuby ships their own xxxx.so files in /PowerRuby/oss/lib (i.e. libssl.so and libssl.so.1.0.0). Not sure if this is potentially problematic because the PASE process is obviously picking up similarly named libs.

  26. Former user Account Deleted

    Ok, Our primary core dump is illegal instruction, caused by attempting to run code near address 0x00000000. PASE/AIX intentionally zeros first few bytes of address 0x0 to catch "bad programs", usually indicating return stack corruption and/or author built/compiled badly. In this case we can see LAST STOP SIGNAL..........4 (SIGILL), clearly indicating an attempt to run code that does not exist at address zero, and, confirmation we see Instruction Address Register also at address zero (IAR=0000000000000000). Also, we see register 2 is also zero (TOC register). Humour, just too many zeros in a row to ignore, so we have found at least one "smoking gun" (SIGILL illegal instruction).

    Now, comes hard part ... why did _RUBY_IBM_DB_BIND_FETCH_HELPER calling RB_HASH_ASET cause a core dump???

    Speculation ... Hashes are notorious for using "performance trickery", aka, thunking "keys/addresses", so look-ups are ultra fast. So, yucky poo, is best description. However, I do not think problem will be actual ruby hash algorithm, because, if hash did not work in ruby, then the whole ruby universe would collapse like a black hole. Therefore, instead, fo love of sanity (my own), i choose to speculate a thread style interaction between ibm_db and ruby hash c code lead to eventual core dump.

    What to do?? Good question. I can think of two actions ... 1) Add thread id to the key of the libdb400.a trace facility. 2) Add roll your own calls into libdb400.a trace facility, for c coders to dump some more data (this case something about hash as it relates to db2 bind).

    PROGRAM: "/POWERRUBY/PRV2R1/BIN/RUBY"
      ARGV AT 2FF22D24
        ARGV[0] "/POWERRUBY/PRV2R1/BIN/RUBY"
        ARGV[1] "BIN/RAILS"
        ARGV[2] "S"
        ARGV[3] "-P50000"
    
    LAST STOP SIGNAL..........4 (SIGILL)
        IAR=0000000000000000
         LR=00000000100CBF04 ST_UPDATE+0X68
    GPR00=00000000100C224C  GPR01=00000000245EE450  GPR02=0000000000000000  GPR03=0000000024A5B620
    
    ISF=245EE450 TS=8000745EE450  NIA=00000011 ***INSTRUCTION ADDRESS NOT WORD-ALIGNED***
    ISF=245EE4C0 TS=8000745EE4C0  NIA=100C224C RB_HASH_ASET+0XF0
    ISF=245EE530 TS=8000745EE530  NIA=D1A8F050 _RUBY_IBM_DB_BIND_FETCH_HELPER+0XEB0
    ISF=245EE5F0 TS=8000745EE5F0  NIA=D1A8FBC8 IBM_DB_FETCH_ASSOC+0X98
    

    Your observation about libssl.xxx, we see both versions in the core dump liest of files, but no idication that SSL anything was involved in the core dump. So, while unpleasant to see, and, cough, a personally satisfying i told you so to power ruby, we just don't know if this plays a role in the eventual core dump.

    0 | 00033FAF | CD4CF5747D002500 | /POWERRUBY/OSS/LIB/LIBSSL.SO
    
    0 | 00033FAF | CD4CF5747D003300 | /USR/LIB/LIBSSL.A
    0 | 00033FAF | CD4CF5747D003380 | /USR/LIB/LIBCRYPTO.A
    
  27. Aaron Bartell reporter

    Thanks for detailing that out.

    What to do?? Good question. I can think of two actions ... 1) Add thread id to the key of the libdb400.a trace facility. 2) Add roll your own calls into libdb400.a trace facility, for c coders to dump some more data (this case something about hash as it relates to db2 bind).

    Are either of those options something I can pursue given I don't (to my knowledge) have access to libdb400.a source code?

  28. Former user Account Deleted

    Mmm ... Open Source... trace version libdb400.a compiled xlc to avoid gcc runtime issues (libgcc.a) ... I will think about it.

    Meanwhile, can you tar a small application that demonstrates the problem? I have following versions on my machine (i don't want to load a new version unless required to recreate ) ...

    bash-4.3$ ls /PowerRuby/
    oss     prV2R0  prV2R1
    
  29. Aaron Bartell reporter

    Here is a repo you can clone.

    PowerRuby hasn't released versions different from what you've specified. You should use prV2R1 as that one errors more often (my perception), though prV2R0 will also error. The READEME.md has setup instructions. Let me know if I've forgotten something. Very vanilla Rails app.

    To set version to prV2R1:

    export PATH=/PowerRuby/prV2R1/bin:$PATH
    
  30. Former user Account Deleted

    Never mind, i built my own rails test ... did not fail fetch... but ... i found coredump error(s) in new trace libdb400.a (stack overrun).

    Please try this new version 1.0.4 on your machine (trace all, stack all) PASE DB2 CLI trace library

  31. Former user Account Deleted

    Tried your test failed rake ... do not really want to go chasing ruby gems, so how can i remove puma thing???

    bash-4.3$ rake db:migrate
    Could not find puma-2.11.1 in any of the sources
    Run `bundle install` to install missing gems.
    
  32. Former user Account Deleted

    BTW -- i like this database.yml (save typing) ...

    default: &default
      adapter: ibm_db
      database: "*LOCAL"
      username: MYID
      password: MYPWD
    
    development:
      <<: *default
    
    test:
      <<: *default
    
    production:
      <<: *default
    
  33. Aaron Bartell reporter

    To use thin instead of puma gem do the following:

    In Gemfile:

    ...
    #gem 'puma'
    gem 'thin'
    
    cd ibmdb_fetchbug
    bundle install
    

    BTW -- i like this database.yml (save typing) ...

    Agreed. I mostly leave it the other way because it is generated that way for me (so zero typing :-).

    Installing new trace util right now.

  34. Former user Account Deleted

    Nope ... all i get is the rails default page ...

    Welcome aboard
    You’re riding Ruby on Rails!
    
  35. Aaron Bartell reporter

    Latest error with new PASE CLI trace 1.0.4.

    Here is the libdb400_trace_355715 log file.

    Here are the flags from /QOpenSys/download/trace-1.0.4-xlc/paseclitrace.ini. Note trace_stack=2 is now working.

    device_type=1
    device_pid=1
    trace_type=1
    trace_stack=2
    trace_break=0
    

    Here is how I invoked it:

    export LIBPATH=/QOpenSys/download/trace-1.0.4-xlc
    export PASETRACE=/QOpenSys/download/trace-1.0.4-xlc/paseclitrace.ini
    export IBM_DB_GIL="00000000000000000000000000000000000000000000"
    
    rails s -p50000
    
  36. Former user Account Deleted

    Never mind ... btu ... this never fails, no matter how many times i refresh users/1.

    So ... dee ... do ... dee ... a little PowerRuby creativity during build of your copy of ibm_db ... no, can't be ... that would be unethical.

    http://lp0364d:5000/users/1
    
     Name: frog luther 22 roch mn 55906
    2015-09-03 20:24:45 UTC
    2015-09-03 20:24:45 UTC
    Edit | Back
    
  37. Aaron Bartell reporter

    Nope ... all i get is the rails default page ...

    1 - Navigate to http://machine:port/users

    2 - Add a user or two.

    3 - Navigate back to http://machine:port/users and repeatedly refresh until error happens.

  38. Aaron Bartell reporter

    Never mind ... btu ... this never fails, no matter how many times i refresh users/1.

    What PowerRuby version are you using? Also, try path /users instead.

  39. Former user Account Deleted

    Never mind ...oh how do i break the news gently ... ruby guys (rails, or you) messed up and shared a hstmt resource across threads.

    If you look at trace, new extra thread id field shows thread #6 using hstmt #3 ok (SQLGetData) -- but -- We look at error and thread #30 also tried to use hstmt #3 (SQLNumResultCols) ... BOOM ...

    Now, timestamp is moved in time, but, still, thread id #6 and #30 seem to be using the same hstmt ... that is NEVER allowed ... ever.

    SQLGetData.355715.1441318642.6.retn SQLRETURN sqlrc 0x1 (1) SQL_SUCCESS_WITH_INFO
    SQLGetData.355715.1441318642.6.parm SQLHSTMT hstmt 0x3 (3)
    :
    SQLNumResultCols.355715.1441318674.30.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR)
    SQLNumResultCols.355715.1441318674.30.parm SQLHSTMT hstmt 0x3 (3)
    
  40. Former user Account Deleted

    Interesting difference on my machine i am not using thin or puma ... cough ... just a thought. Maybe you should try WebBrick and see if all works ...

  41. Former user Account Deleted

    BTW -- using Webrick, never fails, been refreshing for long time (minutes) ...

    Listing users
    Name    Age     City    State   Zip     
    frog luther     22  roch    mn  55906   Show    Edit    Destroy
    lex luther  42  roch    mn  55906   Show    Edit    Destroy
    tod luther  48  roch    mn  55906   Show    Edit    Destroy
    
    New User
    
  42. Aaron Bartell reporter

    Good to know what the issue is. I am now researching to see if anyone else has had the hstmt sharing issue and am empty handed so far.

    I took puma out of the mix and went with Webrick and get same issue/error. Here is the trace from Webrick. Btw, Webrick isn't an option for production.

    $ rails s -p50000
    => Booting WEBrick
    => Rails 4.1.8 application starting in development on http://0.0.0.0:50000
    => Run `rails server -h` for more startup options
    => Notice: server is listening on all interfaces (0.0.0.0). Consider using 127.0.0.1 (--binding option)
    => Ctrl-C to shutdown server
    [2015-09-03 22:47:18] INFO  WEBrick 1.3.1
    [2015-09-03 22:47:18] INFO  ruby 2.1.5 (2014-11-13) [powerpc-aix6.1]
    [2015-09-03 22:47:18] INFO  WEBrick::HTTPServer#start: pid=355833 port=50000
    
  43. Former user Account Deleted

    Yes, so much for Webrick theory, appears thread #3 and #6 tried to use the same hstmt ... BOOM ...

    Yikes, so why is my machine well behaved and yours seems bent on self destruction???

    Here is my ibm_db data ... maybe yours is different???

    bash-4.3$ ls -l /PowerRuby/prV2R1/./lib/ruby/gems/2.1.0/gems/ibm_db-2.5.14-powerpc-aix-6/lib/ibm_db.so
    -rwxr-xr-x    1 qsys     0            750999 Nov 21 2014  /PowerRuby/prV2R1/./lib/ruby/gems/2.1.0/gems/ibm_db-2.5.14-powerpc-aix-6/lib/ibm_db.so
    
    bash-4.3$ rails s -p5000 &
    [2015-09-03 15:53:55] INFO  WEBrick::HTTPServer#start: pid=30234 port=5000
    
    bash-4.3$ ps
       PID    TTY  TIME CMD
     27936  pts/0  0:00 -bsh 
     28897  pts/0  0:00 bash 
     28936  pts/0  0:00 e Gemfile 
     30189  pts/0  0:00 e Gemfile 
     30234  pts/0  0:03 /PowerRuby/prV2R1/bin/ruby 
     30235  pts/0  0:00 ps 
    
    bash-4.3$ dbx -d 100 -a 30234
    Waiting to attach to process 30234 ...
    : ... stuff ...
    (dbx) map
    : ... stuff
    Entry 9:
       Object name: /PowerRuby/prV2R1/lib/ruby/gems/2.1.0/gems/ibm_db-2.5.14-powerpc-aix-6/lib/ibm_db.so
       Text origin:     0xd5ff5000
       Text length:     0x260c2
       Data origin:     0xf14e3745
       Data length:     0x1033
       File descriptor: 0xb
    
  44. Aaron Bartell reporter

    Yikes, so why is my machine well behaved and yours seems bent on self destruction???

    I've had times (measured in hours) where I tried to recreate the error and couldn't. I don't yet know the circumstances that allow for it to not happen.

    $ ls -l /PowerRuby/prV2R1/./lib/ruby/gems/2.1.0/gems/ibm_db-2.5.14-powerpc-aix-6/lib/ibm_db.so
    -rwxr-xr-x    1 qsys     0            750999 Mar 10 22:52 /PowerRuby/prV2R1/./lib/ruby/gems/2.1.0/gems/ibm_db-2.5.14-powerpc-aix-6/lib/ibm_db.so
    
    $ rails s -p50000 &
    [1] 355839
    => Booting WEBrick
    => Rails 4.1.8 application starting in development on http://0.0.0.0:50000
    => Run `rails server -h` for more startup options
    => Notice: server is listening on all interfaces (0.0.0.0). Consider using 127.0.0.1 (--binding option)
    => Ctrl-C to shutdown server
    [2015-09-03 23:03:53] INFO  WEBrick 1.3.1
    [2015-09-03 23:03:53] INFO  ruby 2.1.5 (2014-11-13) [powerpc-aix6.1]
    [2015-09-03 23:03:53] INFO  WEBrick::HTTPServer#start: pid=355839 port=50000
    $ ps
        PID    TTY  TIME CMD
     354242  pts/1  0:00 -bash
     355839  pts/1  0:02 /PowerRuby/prV2R1/bin/ruby bin/rails s -p50000
     355840  pts/1  0:00 ps
    $ dbx -d 100 -a 355839
    Waiting to attach to process 355839 ...
    Successfully attached to /PowerRuby/prV2R1/bin/ruby.
    Type 'help' for help.
    reading symbolic information ...internal error: assertion failed at line 5562 in file object.c
    internal error: assertion failed at line 5562 in file object.c
    . . .
    internal error: assertion failed at line 5562 in file object.c
    
    stopped in __fd_select at 0x2017b4bc ($t1)
    0x2017b4bc (__fd_select+0xbc) 80410014         lwz   r2,0x14(r1)
    (dbx) map
    . . .
    Entry 9:
       Object name: /PowerRuby/prV2R1/lib/ruby/gems/2.1.0/gems/ibm_db-2.5.14-powerpc-aix-6/lib/ibm_db.so
       Text origin:     0xd1a83000
       Text length:     0x260c2
       Data origin:     0x22082745
       Data length:     0x1033
       File descriptor: 0xb
    
  45. Aaron Bartell reporter

    Continuing my research of this issue...

    Currently ibm_db defaults to connect vs pconnect with one primary difference being that connect is implicitly closed and pconnect implicitly remains open. Would changing to pconnect fix our issue? Yes, I realize this would be a hack and not addressing the real issue of sharing a connection across threads.

  46. Former user Account Deleted

    Well, i am not sure, but found something more important ...

    The trace tool has recording 'free(s)' turned off by default, therefore, we can not detect common (mundane) problem of closing a resource, and, reusing. I do not know why i shut off free(s), but i look at this, see, if we see another pattern (*).

    (*) BTW -- warning, do not breath sigh of relief, even if we figure out open/close pattern, still very, very, concerning your machine ruby is choosing to share database resources across threads, simply, a terrible idea because we would have to lock out CLI to one thread user at a time per profile, aka, rope tie rails leaving only one leg in the air twitching (... calf roping rodeo style).

  47. Former user Account Deleted

    Ok, here is a new trace version with free default 'on' v1.0.5 libdb400.a trace. You need to replace your pasetracecli.ini file with free elements toggled on (if using).

    PASE DB2 CLI trace library
    
    At times a PASE side DB2 CLI trace is helpful. 
    
        Attach:trace-1.0.5-xlc.zip 2015–09–08 (version 1.0.5)
            Version 1.0.5 (2015–09–08)
                change default for SQLFree to ‘on’ (was off) 
    
  48. Aaron Bartell reporter

    I've loaded trace-1.0.5-xlc

    Here are the results. Note I reproduced the error many times to give you multiple error samples (not sure if that is helpful).

    Here is my paseclitrace.ini. I kept it the same as was in trace-1.0.5-xlc.zip except I changed trace_stack=2.

    Here's how I am invoking it:

    export LIBPATH=/QOpenSys/download/trace-1.0.5-xlc
    export PASETRACE=/QOpenSys/download/trace-1.0.5-xlc/paseclitrace.ini
    export IBM_DB_GIL="00000000000000000000000000000000000000000000"
    rails s -p50000
    
  49. Former user Account Deleted

    No, we are only seeing errors (we already know invalid handle), we need to see good entries as well ... we are trying to see if one of the threads closed the handle, then another thread (or same) reused the closed handle (without another open).

    You need to set paseclitrace.ini (trace_type=0) ...

    trace_type=0
    trace_stack=2
    
  50. Aaron Bartell reporter

    Here is the new log with trace_type=0

    I am actively reading through the results... still digesting how these logs work. I believe the following line declares a handle of 2 being returned, correct?

    SQLAllocHandle.621559.1441829775.6.parm SQLSMALLINT htype 0x2 (2)
    

    And then this line, where 2 is mentioned, is where that handle is first being used again, correct?

    SQLSetConnectAttr.621559.1441829775.6.walk SQLSetConnectAttr (2 2713 24a03278 fffffffd)
    

    Or maybe a better way to say it: The above line is basically the API call with the parm values each separated with a space?

    What are the 621559 and 1441829775 numbers? I assume the latter is epoch time.

  51. Former user Account Deleted

    What are the 621559 and 1441829775 numbers?

    SQLSetConnectAttr.621559.1441829775.6.walk
    SQLSetConnectAttr - CLI  API
    621559 -  process id or pid of trace job (aka, your ruby web server job).
    1441829775 - time
    6 - thread number
    walk - type of entry in the log (walk the stack)
    

    the following line declares a handle of 2 being returned, correct? Incorrect, 2 type of handle created, you need to look at SQLAllocHandle manual and header file to see what '2' means.

    where 2 is mentioned, is where that handle is first being used again, correct? Well, i did not look at trace, but SQLSetConnectAttr manual, yes i believe first parameter is the handle.

    Unsolicited, work item... So, as you can see the trace simply records numbers for parameters, thereby any volunteer could write a python program that scanned filled in the header file names for the "known" #define numbers ... cough ... any one could do that ... cough, cough, anyone at all ... cough ... not a hint to anyone in particular ... cough, cough, cough.

  52. Former user Account Deleted

    So for education, here is an interesting sequence ...

    We see SQLExecDirect use SQLHSTMT hstmt 0x3 (cool), then ruby finalize_list calls through to SQLFreeHandle htype 0x3/hndl 0x3 (mmmm ... ok), then finalize_list AGAIN calls through to SQLFreeHandle htype 0x3/hndl 0x3 and BOOM sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR).

    SQLExecDirect.621559.1441829776.6.tbeg +++success+++
    SQLExecDirect.621559.1441829776.6.walk dump_SQLExecDirect (0 3 24a2ea10 10)
    SQLExecDirect.621559.1441829776.6.walk SQLExecDirect (3 24a2ea10 10)
    SQLExecDirect.621559.1441829776.6.walk _ruby_ibm_db_SQLExecDirect_helper (?)
    SQLExecDirect.621559.1441829776.6.walk ibm_db_exec (?)
    SQLExecDirect.621559.1441829776.6.retn SQLRETURN sqlrc 0x0 (0) SQL_SUCCESS
    SQLExecDirect.621559.1441829776.6.parm SQLHSTMT hstmt 0x3 (3)
    
    
    SQLFreeHandle.621559.1441829776.6.tbeg +++success+++
    SQLFreeHandle.621559.1441829776.6.walk dump_SQLFreeHandle (0 30003 3)
    SQLFreeHandle.621559.1441829776.6.walk SQLFreeHandle (30003 3)
    SQLFreeHandle.621559.1441829776.6.walk _ruby_ibm_db_free_stmt_struct (?)
    SQLFreeHandle.621559.1441829776.6.walk finalize_list (?)
    SQLFreeHandle.621559.1441829776.6.retn SQLRETURN sqlrc 0x0 (0) SQL_SUCCESS
    SQLFreeHandle.621559.1441829776.6.parm SQLSMALLINT htype 0x3 (3)
    SQLFreeHandle.621559.1441829776.6.parm SQLINTEGER hndl 0x3 (3)
    
    
    SQLFreeHandle.621559.1441829776.6.tbeg ---error---
    SQLFreeHandle.621559.1441829776.6.walk dump_SQLFreeHandle (fffffffe 30003 3)
    SQLFreeHandle.621559.1441829776.6.walk SQLFreeHandle (30003 3)
    SQLFreeHandle.621559.1441829776.6.walk _ruby_ibm_db_free_stmt_struct (?)
    SQLFreeHandle.621559.1441829776.6.walk finalize_list (?)
    SQLFreeHandle.621559.1441829776.6.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR)
    SQLFreeHandle.621559.1441829776.6.parm SQLSMALLINT htype 0x3 (3)
    SQLFreeHandle.621559.1441829776.6.parm SQLINTEGER hndl 0x3 (3)
    
  53. Former user Account Deleted

    Last entry "interesting" ...

    Reason this is interesting is that it is very easy to imagine scenarios where this double free results in unintentional free of a working handle in CLI. Expert knowledge (mine), IBM i CLI re-uses lowest number handle it can find, therefore in a mutli thread environment using DB2 'handles' (like rails), very easy to 'make up' scenarios where one thread has done a allocation that 're-used" a number timed between the first and second delete and lost a perfectly good handle.

  54. Former user Account Deleted

    BTW -- i have not looked through all the data yet, so we do not know the double free is the "nad actor", but it is a smoking gun, therefore for education "how do i read trace", this is a good abstract conversation.

  55. Former user Account Deleted

    BTW -- sequences that look like this may me VERY uncomfortable (RUBY CRAZY) ... aka ... i have no idea what a rb_postponed_job_flush actually does, but the garbage collector fires gc_finalize_deferred, which eventually calls SQLFreeHandle and BOOM SQL_INVALID_HANDLE (SQL_ERROR).

    Not saying is problem yet, but anything in garbage collection that runs "defered", especially with a double free already identified is just asking for big toruble.

    SQLFreeHandle.621559.1441829897.19.tbeg ---error---
    SQLFreeHandle.621559.1441829897.19.walk dump_SQLFreeHandle (fffffffe 30003 3)
    SQLFreeHandle.621559.1441829897.19.walk SQLFreeHandle (30003 3)
    SQLFreeHandle.621559.1441829897.19.walk _ruby_ibm_db_free_stmt_struct (?)
    SQLFreeHandle.621559.1441829897.19.walk finalize_list (?)
    SQLFreeHandle.621559.1441829897.19.walk gc_finalize_deferred (?)
    SQLFreeHandle.621559.1441829897.19.walk rb_postponed_job_flush (?)
    SQLFreeHandle.621559.1441829897.19.walk rb_threadptr_execute_interrupts.part.38 (?)
    
    SQLFreeHandle.621559.1441829897.19.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR)
    SQLFreeHandle.621559.1441829897.19.parm SQLSMALLINT htype 0x3 (3)
    SQLFreeHandle.621559.1441829897.19.parm SQLINTEGER hndl 0x3 (3)
    
  56. Former user Account Deleted

    Mmm ... downloaded you trace file ... only SQL_ERROR i see are all SQL_ERROR. Did this actually fail??? I though your other file had error in SQLGetData (or something)???

    [adc@oc7083008330 aaron-2015-06-24]$ grep SQL_ERROR trace-2015-09-10.txt 
    SQLFreeHandle.621559.1441829776.6.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR)
    SQLFreeHandle.621559.1441829877.14.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR)
    SQLFreeHandle.621559.1441829897.19.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR)
    SQLFreeHandle.621559.1441829897.19.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR)
    SQLFreeHandle.621559.1441829897.19.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR)
    SQLFreeHandle.621559.1441829897.19.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR)
    SQLFreeHandle.621559.1441829897.19.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR)
    SQLFreeHandle.621559.1441829897.19.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR)
    SQLFreeHandle.621559.1441829897.19.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR)
    
  57. Former user Account Deleted

    I had to look back through this issue to find it was SQLNumResultCols (not SQLGetData), but again, latest trace all we see is SQL_ERROR on SQL_ERROR. Did this actually fail???

    SQLNumResultCols.355715.1441318674.30.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR)
    
  58. Former user Account Deleted

    Sorry ... did you test really fail, aka, not return rows of data (original issue)???

    Old trace SQLNumResultCols ... SQL_INVALID_HANDLE (SQL_ERROR)

    SQLNumResultCols.355715.1441318674.30.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR)
    

    New trace ... only SQLFreeHandle SQL_INVALID_HANDLE (SQL_ERROR)

    [adc@oc7083008330 aaron-2015-06-24]$ grep SQL_ERROR trace-2015-09-10.txt 
    SQLFreeHandle.621559.1441829776.6.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR)
    SQLFreeHandle.621559.1441829877.14.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR)
    SQLFreeHandle.621559.1441829897.19.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR)
    SQLFreeHandle.621559.1441829897.19.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR)
    SQLFreeHandle.621559.1441829897.19.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR)
    SQLFreeHandle.621559.1441829897.19.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR)
    SQLFreeHandle.621559.1441829897.19.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR)
    SQLFreeHandle.621559.1441829897.19.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR)
    SQLFreeHandle.621559.1441829897.19.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR)
    
  59. Aaron Bartell reporter

    I had to look back through this issue to find it was SQLNumResultCols (not SQLGetData), but again, latest trace all we see is SQL_ERROR on SQL_ERROR. Did this actually fail???

    My fault. I was monitoring the trace file with a grep to look for "error" and not watching what error was actually produced. Sorry for wasting your time.

    Here is the log with SQLNumResultCols error. Had to put it on my personal server because bitbucket told me it was too large for their Snippets (20MB). Line 268,937 is one instance of the error.

    We see SQLExecDirect use SQLHSTMT hstmt 0x3 (cool), then ruby finalize_list calls through to SQLFreeHandle htype 0x3/hndl 0x3 (mmmm ... ok), then finalize_list AGAIN calls through to SQLFreeHandle htype 0x3/hndl 0x3 and BOOM sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR).

    Which then begs the question, is it our ibm_db implementation that is combining multiple SQLExecDirect statements into a single handle when ActiveRecord was expecting them to be separate? Or maybe a different way to ask the same question: When the web transaction completes are there handles still open that should be closed?

    Unsolicited, work item... So, as you can see the trace simply records numbers for parameters, thereby any volunteer could write a python program that scanned filled in the header file names for the "known" #define numbers ... cough ... any one could do that ... cough, cough, anyone at all ... cough ... not a hint to anyone in particular ... cough, cough, cough.

    I definitely caught your hint :-) ...but am not exactly sure what you envision the end result accomplishing. Is it so we can more easily know which line of code in ibm_db.c is causing the error?

  60. Former user Account Deleted

    Well, here is the smoking gun ... breifly ... i do not see the characteristic double free, so this may be the case were the double delete gets out of sequence

    1) SQLExecDirect worked fine hstmt 0x3
    2) rb_threadptr_execute_interrupts->rb_postponed_job_flush->_ruby_ibm_db_free_stmt_struct->SQLFreeHandle hndl 0x3 (3)
    3) BOOM ... SQLNumResultCols hstmt 0x3 (3)
    

    cut/paste from trace, these are back-2-back entries ...

    good, good, ...
    
    SQLExecDirect.638756.1441906535.73.tbeg +++success+++
    SQLExecDirect.638756.1441906535.73.walk dump_SQLExecDirect (0 3 23b0e770 1a)
    SQLExecDirect.638756.1441906535.73.walk SQLExecDirect (3 23b0e770 1a)
    SQLExecDirect.638756.1441906535.73.walk _ruby_ibm_db_SQLExecDirect_helper (?)
    SQLExecDirect.638756.1441906535.73.walk ibm_db_exec (?)
    SQLExecDirect.638756.1441906535.73.walk call_cfunc_m1 (?)
    SQLExecDirect.638756.1441906535.73.walk vm_call_cfunc_with_frame (?)
    SQLExecDirect.638756.1441906535.73.retn SQLRETURN sqlrc 0x0 (0) SQL_SUCCESS
    SQLExecDirect.638756.1441906535.73.parm SQLHSTMT hstmt 0x3 (3)
    
    SQLFreeHandle.638756.1441906535.73.tbeg +++success+++
    SQLFreeHandle.638756.1441906535.73.walk dump_SQLFreeHandle (0 30003 3)
    SQLFreeHandle.638756.1441906535.73.walk SQLFreeHandle (30003 3)
    SQLFreeHandle.638756.1441906535.73.walk _ruby_ibm_db_free_stmt_struct (?)
    SQLFreeHandle.638756.1441906535.73.walk finalize_list (?)
    SQLFreeHandle.638756.1441906535.73.walk gc_finalize_deferred (?)
    SQLFreeHandle.638756.1441906535.73.walk rb_postponed_job_flush (?)
    SQLFreeHandle.638756.1441906535.73.walk rb_threadptr_execute_interrupts.part.38 (?)
    SQLFreeHandle.638756.1441906535.73.retn SQLRETURN sqlrc 0x0 (0) SQL_SUCCESS
    SQLFreeHandle.638756.1441906535.73.parm SQLSMALLINT htype 0x3 (3)
    SQLFreeHandle.638756.1441906535.73.parm SQLINTEGER hndl 0x3 (3)
    
    SQLNumResultCols using a handle that was already closed
    
    SQLNumResultCols.638756.1441906535.73.tbeg ---error---
    SQLNumResultCols.638756.1441906535.73.walk dump_SQLNumResultCols (fffffffe 3 22888e54)
    SQLNumResultCols.638756.1441906535.73.walk SQLNumResultCols (3 22888e54)
    SQLNumResultCols.638756.1441906535.73.walk _ruby_ibm_db_SQLNumResultCols_helper (?)
    SQLNumResultCols.638756.1441906535.73.walk _ruby_ibm_db_get_result_set_info (?)
    SQLNumResultCols.638756.1441906535.73.walk ibm_db_result_cols (?)
    SQLNumResultCols.638756.1441906535.73.walk call_cfunc_m1 (?)
    SQLNumResultCols.638756.1441906535.73.walk vm_call_cfunc_with_frame (?)
    SQLNumResultCols.638756.1441906535.73.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR)
    SQLNumResultCols.638756.1441906535.73.parm SQLHSTMT hstmt 0x3 (3)
    
    next we see a reallocation of stamt handle #3 (too late for SQLNumResultCols)
    
    SQLAllocHandle.638756.1441906535.73.tbeg +++success+++
    SQLAllocHandle.638756.1441906535.73.walk dump_SQLAllocHandle (0 30003 2 23b1a834)
    SQLAllocHandle.638756.1441906535.73.walk SQLAllocHandle (30003 2 23b1a834)
    SQLAllocHandle.638756.1441906535.73.walk ibm_db_exec (?)
    SQLAllocHandle.638756.1441906535.73.walk call_cfunc_m1 (?)
    SQLAllocHandle.638756.1441906535.73.walk vm_call_cfunc_with_frame (?)
    SQLAllocHandle.638756.1441906535.73.retn SQLRETURN sqlrc 0x0 (0) SQL_SUCCESS
    SQLAllocHandle.638756.1441906535.73.parm SQLSMALLINT htype 0x3 (3)
    SQLAllocHandle.638756.1441906535.73.parm SQLINTEGER ihnd 0x2 (2)
    SQLAllocHandle.638756.1441906535.73.parm SQLINTEGER* ohnd 0x23b1a834 (598845492)
    SQLAllocHandle.638756.1441906535.73.phex 23b1a834 : 00000003
    
  61. Former user Account Deleted

    BTW --

    Ruby script initiated functions stack call_cfunc_m1->(ibm_db_exec, ibm_db_result_cols, ibm_db_result_cols)

    -- but --

    Ruby garbage collector initiated functions with stack gc_finalize_deferred->..-> (_ruby_ibm_db_free_stmt_struct).

    Very interesting, possible ruby garbage collecting is in fact the actual problem for both double delete and out of sequence release.

  62. Former user Account Deleted

    Ruby garbage collection would relate back to "script scope" (i think), where out of scope object could be "collected". So, possibilities (may be wrong), perhaps needed something in ibm_db.c code saying "ruby ref count leave me alone" (i doubt), or , Ruby script has hand on a stmt that goes out of scope and is free (garbage collected). Can you check the ruby script code for scope of the statement object ???

    When the Ruby garbage collector is invoked, it has a mark phase and a sweep phase. 
    The mark phase marks all objects in the system by marking:
    
        all objects referenced by a ruby stack frame (e.g. local variables)
        all globally accessible objects (e.g. referred to by a constant or global variable) and their children/referents, and
        all objects referred to by a reference on the stack, as well as those objects' children/referents.
    
    as well as a number of other objects that are not important to this discussion. 
    The sweep phase then destroys any objects that are not accessible (i.e. those that were not marked).
    
  63. Aaron Bartell reporter

    Ok, so this entry is full of observations.

    First I reviewed class level variables (i.e. @@).

    Line 3186, variable @@open_classing_done. I believe this is the only class variable used in ibm_db_adapter.rb.

    Moving on...

    Most Ruby methods in ibm_db_adapter.rb obtain a local variable for stmt (or pstmt) and release it (i.e. IBM_DB.free_stmt(stmt) if stmt) in the same method, except the fetch_data method below. It receives a stmt allocated upstream, in execute or exec_query and does a free_stmt(...) within vs. letting the caller do it. As best I can tell the caller's stmt variable would still be valid, though the handle it once contained is no longer valid. Again, an observation.

          def fetch_data(stmt)
            if(stmt)
              begin
                return @servertype.select(stmt)
              rescue StandardError => fetch_error # Handle driver fetch errors
                error_msg = IBM_DB.getErrormsg(stmt, IBM_DB::DB_STMT )
                if error_msg && !error_msg.empty?
                  raise StatementInvalid,"Failed to retrieve data: #{error_msg}"
                else
                  error_msg = "An unexpected error occurred during data retrieval"
                  error_msg = error_msg + ": #{fetch_error.message}" if !fetch_error.message.empty?
                  raise error_msg
                end
              ensure
              # Ensures to free the resources associated with the statement
                IBM_DB.free_stmt(stmt) if stmt
              end
            end
          end
    

    It should be noted fetch_data() is only invoked from the select method. The select method, below, procures a stmt handle but never does a free_stmt, because fetch_data() does. I bring this up because I know RPG, at some point in time, had issues with pointers (variables?) that were allocated in one sub proc and deallocated in another (don't recall exact details, but I was bitten by it).

          def select(sql, name = nil, binds = [])
            # Replaces {"= NULL" with " IS NULL"} OR {"IN (NULL)" with " IS NULL"}
            sql.gsub!( /(=\s*NULL|IN\s*\(NULL\))/i, " IS NULL" )
    
            results = []
    
            if(binds.nil? || binds.empty?)
              stmt = execute(sql, name)
            else
              stmt = exec_query(sql, name, binds)
            end
    
            cols = IBM_DB.resultCols(stmt)
    
            if( stmt ) 
              results = fetch_data(stmt)
            end
    
            if(@isAr3)
              return results
            else
              return ActiveRecord::Result.new(cols, results)
            end
          end
    

    Method exec_query procures stmt and returns it to caller. The above select method is one such caller, but notice how return false is used instead of raising an exception like execute does.

          def exec_query(sql, name = 'SQL', binds = [])
            begin
              param_array = binds.map do |column,value|
                quote_value_for_pstmt(value, column)
              end
    
              stmt = prepare(sql, name)
    
               if( stmt )
                 if(execute_prepared_stmt(stmt, param_array))
                   return stmt
                 end
               else
                 return false
               end
            ensure
              @offset = @limit = nil
            end
          end
    

    There's potentially some funny stuff going on in method last_generated, show below. Note how it states the passed in stmt is used for IDS but not for DB2. Well, it does a IBM_DB.free_stmt regardless of whether DB2 or IDS is being used. Might account for the SQLFreeHandle SQL_INVALID_HANDLE (SQL_ERROR) we saw earlier? Though my code should not be calling this as I am doing SELECTs and not INSERTs.

          # Returns the last automatically generated ID.
          # This method is required by the +insert+ method
          # The "stmt" parameter is ignored for DB2 but used for IDS
          def last_generated_id(stmt)
            # Queries the db to obtain the last ID that was automatically generated
            sql = "SELECT IDENTITY_VAL_LOCAL() FROM SYSIBM.SYSDUMMY1"
            stmt = IBM_DB.prepare(@adapter.connection, sql)
            if(stmt)
              if(IBM_DB.execute(stmt, nil))
                begin
                  # Fetches the only record available (containing the last id)
                  IBM_DB.fetch_row(stmt)
                  # Retrieves and returns the result of the query with the last id.
                  IBM_DB.result(stmt,0)
                rescue StandardError => fetch_error # Handle driver fetch errors
                  error_msg = IBM_DB.getErrormsg(stmt, IBM_DB::DB_STMT )
                  if error_msg && !error_msg.empty?
                    raise "Failed to retrieve last generated id: #{error_msg}"
                  else
                    error_msg = "An unexpected error occurred during retrieval of last generated id"
                    error_msg = error_msg + ": #{fetch_error.message}" if !fetch_error.message.empty?
                    raise error_msg
                  end
                ensure  # Free resources associated with the statement
                  IBM_DB.free_stmt(stmt) if stmt
                end
              else
                error_msg = IBM_DB.getErrormsg(stmt, IBM_DB::DB_STMT )
                IBM_DB.free_stmt(stmt) if stmt
                if error_msg && !error_msg.empty?
                  raise "Failed to retrieve last generated id: #{error_msg}"
                else
                  error_msg = "An unexpected error occurred during retrieval of last generated id"
                  raise error_msg
                end
              end
            else
              error_msg = IBM_DB.getErrormsg(@adapter.connection, IBM_DB::DB_CONN )
              if error_msg && !error_msg.empty?
                raise "Failed to retrieve last generated id due to error: #{error_msg}"
              else
                raise StandardError.new('An unexpected error occurred during retrieval of last generated id')
              end
            end
          end
    

    Is this the type of research you were looking for?

    Side comment: There is A LOT of extra code in ibm_db_adapter.rb that has nothing to do with our implementation (i.e. classes IBM_IDS, IBM_DB2_ZOS_8, IBM_DB2_ZOS, IBM_DB2_LUW_COBRA, etc). Given some Ruby methods override the abstract/base class methods it makes it all the more cumbersome to search for things easily. Wondering what your thoughts are of removing these sections of code?

  64. Former user Account Deleted

    Removing code (not IBM i platform) ... mmm ... well ... gee ... more than bit of politics ...

    First, if we stray too far, we may never merge back into more global IBM repository.

    However, at times, i suspect our version may work better remote Linux/Windows to IBM i, because we are interested in IBM i working. So, i guess our folks would not be much interested in Z/OS, and, we likely only interested in LUW DB2 Connect to IBM i (not LUW DB2 per say). SO, if you think you can find the limbs to trim and still have allow the Windows/Linux connect to IBM i emote (via DB2 Connect), then ... ok.

  65. Former user Account Deleted

    As far as ibm_db_adapter.rb research ... yes

    I have not had time to think about your observations, so bit unwise to offer suggestion, but ...

    Suggestion, i wonder if you added a bit of ruby print code to dump/output with similar time stamps to the trace log ... maybe you will see correlations.

  66. Aaron Bartell reporter

    Suggestion, i wonder if you added a bit of ruby print code to dump/output with similar time stamps to the trace log ... maybe you will see correlations.

    I added rake task "trace:run" to the ibmdb_fetchbug repo to use the TracePoint class for getting in-depth call stacks. To run you do the following:

    $ cd ibmdb_fetchbug   
    $ rake trace:run
    

    NOTE: This doesn't reproduce the error and is instead a bit of code we can use in ibm_db_adapter.rb (I need to get some other stuff out the door, but wanted to convey this to help both of us).

    You can change ibmdb_fetchbug/lib/task/trace.rake to have different types of output. I limited it to just ibm_db_adapter.rb (hard coded) for now. note it also allows tracing of Ruby-to-C calls.

    Here is the output. Log layout is <classname>.<method_name>:<lineno>:<epoch>.<Thread.current.object_id>

    % rake trace:run
    Query results...
    #<Class:ActiveRecord::Base>.ibm_db_connection:281.1442261472.271838790
    ActiveRecord::ConnectionAdapters::TableDefinition.initialize:711.1442261472.271838790
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.initialize:890.1442261472.271838790
    ActiveRecord::ConnectionAdapters::IBM_DB2_I5.initialize:3231.1442261472.271838790
    ActiveRecord::ConnectionAdapters::IBM_DB2.initialize:2621.1442261472.271838790
    ActiveRecord::ConnectionAdapters::IBM_DataServer.initialize:2169.1442261472.271838790
    ActiveRecord::ConnectionAdapters::IBM_DataServer.set_schema:2294.1442261472.271838790
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.execute:1575.1442261472.271838790
    ActiveRecord::ConnectionAdapters::IBM_DataServer.execute:2278.1442261472.271838790
    Arel::Visitors::ToSql.initialize:3755.1442261472.271838790
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.active?:1086.1442261472.271838790
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.reconnect!:1131.1442261472.271838790
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.disconnect!:1137.1442261472.271838790
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.connect:1094.1442261472.271838790
    ActiveRecord::ConnectionAdapters::IBM_DataServer.set_schema:2294.1442261472.271838790
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.execute:1575.1442261472.271838790
    ActiveRecord::ConnectionAdapters::IBM_DataServer.execute:2278.1442261472.271838790
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.to_sql:1050.1442261472.271838790
    Arel::Visitors::IBM_DB.visit_Arel_Nodes_SelectStatement:3776.1442261472.271838790
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.quote_column_name:1854.1442261472.271838790
    ActiveRecord::ConnectionAdapters::HostedDataServer.check_reserved_words:3108.1442261472.271838790
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.add_limit_offset!:1706.1442261472.271838790
    ActiveRecord::ConnectionAdapters::IBM_DB2.query_offset_limit:2947.1442261472.271838790
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.select:1273.1442261472.271838790
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.execute:1575.1442261472.271838790
    ActiveRecord::ConnectionAdapters::IBM_DataServer.execute:2278.1442261472.271838790
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.fetch_data:1236.1442261472.271838790
    ActiveRecord::ConnectionAdapters::IBM_DataServer.select:2208.1442261472.271838790
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.columns:2058.1442261472.271838790
    ActiveRecord::ConnectionAdapters::IBM_DB2_I5.columns:3317.1442261472.271838790
    ActiveRecord::ConnectionAdapters::IBM_DataServer.columns:2531.1442261472.271838790
    ActiveRecord::ConnectionAdapters::IBM_DB2.set_case:3045.1442261472.271838790
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.serverschema:882.1442261472.271838790
    ActiveRecord::ConnectionAdapters::IBM_DB2.set_case:3045.1442261472.271838790
    ActiveRecord::ConnectionAdapters::IBM_DB2.set_case:3045.1442261472.271838790
    ActiveRecord::ConnectionAdapters::IBM_DBColumn.simplified_type:584.1442261472.271838790
    ActiveRecord::ConnectionAdapters::IBM_DBColumn.type_cast:569.1442261472.271838790
    ActiveRecord::ConnectionAdapters::IBM_DBColumn.simplified_type:584.1442261472.271838790
    ActiveRecord::ConnectionAdapters::IBM_DBColumn.type_cast:569.1442261472.271838790
    ActiveRecord::ConnectionAdapters::IBM_DBColumn.simplified_type:584.1442261472.271838790
    ActiveRecord::ConnectionAdapters::IBM_DBColumn.type_cast:569.1442261472.271838790
    ActiveRecord::ConnectionAdapters::IBM_DBColumn.simplified_type:584.1442261472.271838790
    ActiveRecord::ConnectionAdapters::IBM_DBColumn.type_cast:569.1442261472.271838790
    ActiveRecord::ConnectionAdapters::IBM_DBColumn.simplified_type:584.1442261472.271838790
    ActiveRecord::ConnectionAdapters::IBM_DBColumn.type_cast:569.1442261472.271838790
    ActiveRecord::ConnectionAdapters::IBM_DBColumn.simplified_type:584.1442261472.271838790
    ActiveRecord::ConnectionAdapters::IBM_DBColumn.type_cast:569.1442261472.271838790
    ActiveRecord::ConnectionAdapters::IBM_DBColumn.simplified_type:584.1442261472.271838790
    ActiveRecord::ConnectionAdapters::IBM_DBColumn.type_cast:569.1442261472.271838790
    ActiveRecord::ConnectionAdapters::IBM_DBColumn.simplified_type:584.1442261472.271838790
    ActiveRecord::ConnectionAdapters::IBM_DBColumn.type_cast:569.1442261472.271838790
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.tables:1977.1442261472.271838790
    ActiveRecord::ConnectionAdapters::IBM_DB2.set_case:3045.1442261472.271838790
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.primary_key:2018.1442261472.271838790
    ActiveRecord::ConnectionAdapters::IBM_DB2.set_case:3045.1442261472.271838790
    ActiveRecord::ConnectionAdapters::IBM_DB2.set_case:3045.1442261472.271838790
    ActiveRecord::ConnectionAdapters::IBM_DBColumn.type_cast:569.1442261472.271838790
    asdf
    ActiveRecord::ConnectionAdapters::IBM_DBColumn.type_cast:569.1442261472.271838790
    asdfasdf
    
  67. Former user Account Deleted

    Mmm ... i don't understand. Any "ruby service" that no longer reproduces the error is lost on me.

    Again, reminder, my machine does not reproduce this error (ever), so anything done for this issue, tools and/or actual debug, needs to take place on your machine.

  68. Former user Account Deleted

    Just a thought ... WE have identified ruby garbage collection (gc) on your machine appears overly aggressive throwing out trash, this case, our DB2 statements. Funny part, this does not happen on my machine (ever). Obvious speculation, your version of Ruby is different than mine, possibly newer than my version of Ruby.

    Ruby gc wants to play "rough", perhaps we should modify ruby c code so ruby can't throw out our statements, aka, we take out our own trash. Today (i think), we are using correct ruby c Data_Wrap_Struct, maybe take drastic action to get out of ruby garbage collection issue with c code (very sad day for ruby however).

    SQLFreeHandle.638756.1441906535.73.tbeg +++success+++
    SQLFreeHandle.638756.1441906535.73.walk dump_SQLFreeHandle (0 30003 3)
    SQLFreeHandle.638756.1441906535.73.walk SQLFreeHandle (30003 3)
    SQLFreeHandle.638756.1441906535.73.walk _ruby_ibm_db_free_stmt_struct (?)
    SQLFreeHandle.638756.1441906535.73.walk finalize_list (?)
    SQLFreeHandle.638756.1441906535.73.walk gc_finalize_deferred (?)
    SQLFreeHandle.638756.1441906535.73.walk rb_postponed_job_flush (?)
    SQLFreeHandle.638756.1441906535.73.walk rb_threadptr_execute_interrupts.part.38 (?)
    SQLFreeHandle.638756.1441906535.73.retn SQLRETURN sqlrc 0x0 (0) SQL_SUCCESS
    SQLFreeHandle.638756.1441906535.73.parm SQLSMALLINT htype 0x3 (3)
    SQLFreeHandle.638756.1441906535.73.parm SQLINTEGER hndl 0x3 (3)
    
  69. Aaron Bartell reporter

    Here is some version info from two different machines that both have the error. I am definitely using a later version that you are (unless they gave you v1.0.8), but I've also been able to recreate on both versions.

    ##Customer Machine with PowerRuby v1.0.7

    $ /PowerRuby/prV2R0/bin/ruby -v
    ruby 2.0.0p598 (2014-11-13 revision 48408) [powerpc-aix6.1.0.0]
    
    ***they don't have prV2R1 installed per my recommendation at the time***
    

    ##KrengelTech machine at v1.0.8 (latest release, though not available to public to my knowledge)

    $ /PowerRuby/prV2R0/bin/ruby -v
    ruby 2.0.0p643 (2015-02-25 revision 49749) [powerpc-aix6.1.0.0]
    
    $ /PowerRuby/prV2R1/bin/ruby -v
    ruby 2.1.5p273 (2014-11-13 revision 48405) [powerpc-aix6.1]
    

    Could you convey your ruby versions back to this thread so we can have it noted?

    maybe take drastic action to get out of ruby garbage collection issue with c code (very sad day for ruby however).

    I think PowerRuby team would need to be involved with that as they hold the compile process.

    Besides, I thought garbage collection wasn't really the issue and instead you said handles should never be shared across threads? Or is it possible we have two issues?

    ##Access to a machine On final note, I now have our Litmis Spaces effort in beta and you could sign up for an account so you can be working with an environment that produces the error. Here is a mp4 video (100MB download) that shows how to setup an account. You'd select a PowerRuby environment instead of a Node.js one. And then git clone git@bitbucket.org:aaronbartell/ibmdb_fetchbug.git to get the code. And then replace the `database.yml' in folder ibmdb_fetchbug with the one that was generated for you (dynamically named directory in your /home directory). Or sign up for an account and I can configure everything for you.

  70. Former user Account Deleted

    My version ... appears to match your customer, assuming customer sees 'the' problem??

    bash-4.3$ /PowerRuby/prV2R0/bin/ruby -v
    ruby 2.0.0p598 (2014-11-13 revision 48408) [powerpc-aix6.1.0.0]
    
  71. Former user Account Deleted

    Two issues or multiple thread issue ... Well, another cut of trace data ...

    We may use SQLAllocEnv as start point for any "web request", env alloc is first thing happens in ibm_db. I removed front part of data becasue only thread #6 was running (and all worked). Unfortunately, later, we see multiple threads acting on DB2 resources. In truth, if all thread DB2 use synchronized correctly (moon blue, ok tuesday, but not firday, etc.), threads could share resource. But, Ruby/Rails wants I/O operations to happen without holding the GIL, so, Ruby/Rails should never share resources like DB2 (any other PHD disagree yapping is likely rooted in dude that only knows MySql -- limited experience).

    So, i do not see the multi-thread smoking gun in the data below, even when factoring multiple threads. However, we can see Ruby garbage collector apparently toss out a perfectly good hstmt, and, next SQL operatin try to use it.

    BTW -- sifting between topics here at lab, so maybe you see a pattern that let's ruby gc off the hook, i am failing to find. yes, i agree, seems like ruby could not get this garbage collecting thing wrong, so i hope, hope, hope, this is something stupid in ibm_db.

    > grep "hstmt 0x3\|hndl 0x3\|htype 0x3\|walk ibm\|walk gc/|SQL_ERROR" trace-2015-09-10.txt
    :
    SQLAllocEnv.621559.1441829785.6.walk ibm_db_connect (?)
    SQLGetEnvAttr.621559.1441829785.6.walk ibm_db_connect (?)
    SQLGetEnvAttr.621559.1441829785.6.walk ibm_db_connect (?)
    SQLSetEnvAttr.621559.1441829785.6.walk ibm_db_connect (?)
    SQLAllocHandle.621559.1441829785.6.walk ibm_db_connect (?)
    SQLSetConnectAttr.621559.1441829785.6.walk ibm_db_connect (?)
    SQLConnect.621559.1441829785.6.walk ibm_db_connect (?)
    SQLGetConnectAttr.621559.1441829785.6.walk ibm_db_connect (?)
    SQLGetInfo.621559.1441829785.6.walk ibm_db_connect (?)
    SQLAllocHandle.621559.1441829785.6.walk ibm_db_exec (?)
    SQLAllocHandle.621559.1441829785.6.parm SQLSMALLINT htype 0x3 (3)
    SQLExecDirect.621559.1441829785.6.walk ibm_db_exec (?)
    SQLExecDirect.621559.1441829785.6.parm SQLHSTMT hstmt 0x3 (3)
    SQLDisconnect.621559.1441829785.12.walk ibm_db_close (?)
    SQLFreeHandle.621559.1441829785.12.walk ibm_db_close (?)
    SQLFreeHandle.621559.1441829785.12.walk ibm_db_close (?)
    
    SQLAllocEnv.621559.1441829785.12.walk ibm_db_connect (?)
    SQLGetEnvAttr.621559.1441829785.12.walk ibm_db_connect (?)
    SQLGetEnvAttr.621559.1441829785.12.walk ibm_db_connect (?)
    SQLSetEnvAttr.621559.1441829785.12.walk ibm_db_connect (?)
    SQLAllocHandle.621559.1441829785.12.walk ibm_db_connect (?)
    SQLSetConnectAttr.621559.1441829785.12.walk ibm_db_connect (?)
    SQLConnect.621559.1441829785.12.walk ibm_db_connect (?)
    SQLGetConnectAttr.621559.1441829785.12.walk ibm_db_connect (?)
    SQLGetInfo.621559.1441829785.12.walk ibm_db_connect (?)
    SQLAllocHandle.621559.1441829785.12.walk ibm_db_exec (?)
    SQLAllocHandle.621559.1441829785.12.parm SQLSMALLINT htype 0x3 (3)
    SQLExecDirect.621559.1441829785.12.walk ibm_db_exec (?)
    SQLExecDirect.621559.1441829785.12.parm SQLHSTMT hstmt 0x3 (3)
    SQLDisconnect.621559.1441829785.8.walk ibm_db_close (?)
    SQLFreeHandle.621559.1441829785.8.walk ibm_db_close (?)
    SQLFreeHandle.621559.1441829785.8.walk ibm_db_close (?)
    
    SQLAllocEnv.621559.1441829785.8.walk ibm_db_connect (?)
    SQLGetEnvAttr.621559.1441829785.8.walk ibm_db_connect (?)
    SQLGetEnvAttr.621559.1441829785.8.walk ibm_db_connect (?)
    SQLSetEnvAttr.621559.1441829785.8.walk ibm_db_connect (?)
    SQLAllocHandle.621559.1441829785.8.walk ibm_db_connect (?)
    SQLSetConnectAttr.621559.1441829785.8.walk ibm_db_connect (?)
    SQLConnect.621559.1441829785.8.walk ibm_db_connect (?)
    SQLGetConnectAttr.621559.1441829785.8.walk ibm_db_connect (?)
    SQLGetInfo.621559.1441829785.8.walk ibm_db_connect (?)
    SQLAllocHandle.621559.1441829785.8.walk ibm_db_exec (?)
    SQLAllocHandle.621559.1441829785.8.parm SQLSMALLINT htype 0x3 (3)
    SQLExecDirect.621559.1441829785.8.walk ibm_db_exec (?)
    SQLExecDirect.621559.1441829785.8.parm SQLHSTMT hstmt 0x3 (3)
    SQLDisconnect.621559.1441829876.13.walk ibm_db_close (?)
    SQLFreeHandle.621559.1441829876.13.walk ibm_db_close (?)
    SQLFreeHandle.621559.1441829876.13.walk ibm_db_close (?)
    
    SQLAllocEnv.621559.1441829876.13.walk ibm_db_connect (?)
    SQLGetEnvAttr.621559.1441829876.13.walk ibm_db_connect (?)
    SQLGetEnvAttr.621559.1441829876.13.walk ibm_db_connect (?)
    SQLSetEnvAttr.621559.1441829876.13.walk ibm_db_connect (?)
    SQLAllocHandle.621559.1441829876.13.walk ibm_db_connect (?)
    SQLSetConnectAttr.621559.1441829876.13.walk ibm_db_connect (?)
    SQLConnect.621559.1441829876.13.walk ibm_db_connect (?)
    SQLGetConnectAttr.621559.1441829876.13.walk ibm_db_connect (?)
    SQLGetInfo.621559.1441829876.13.walk ibm_db_connect (?)
    SQLAllocHandle.621559.1441829876.13.walk ibm_db_exec (?)
    SQLAllocHandle.621559.1441829876.13.parm SQLSMALLINT htype 0x3 (3)
    SQLExecDirect.621559.1441829876.13.walk ibm_db_exec (?)
    SQLExecDirect.621559.1441829876.13.parm SQLHSTMT hstmt 0x3 (3)
    SQLAllocHandle.621559.1441829876.13.walk ibm_db_exec (?)
    SQLAllocHandle.621559.1441829876.13.parm SQLSMALLINT htype 0x3 (3)
    SQLExecDirect.621559.1441829876.13.walk ibm_db_exec (?)
    SQLNumResultCols.621559.1441829876.13.walk ibm_db_result_cols (?)
    SQLBindCol.621559.1441829876.13.walk ibm_db_fetch_array (?)
    SQLBindCol.621559.1441829876.13.walk ibm_db_fetch_array (?)
    SQLBindCol.621559.1441829876.13.walk ibm_db_fetch_array (?)
    SQLFetch.621559.1441829876.13.walk ibm_db_fetch_array (?)
    SQLGetData.621559.1441829876.13.walk ibm_db_fetch_array (?)
    SQLGetData.621559.1441829876.13.walk ibm_db_fetch_array (?)
    SQLGetData.621559.1441829876.13.walk ibm_db_fetch_array (?)
    SQLGetData.621559.1441829876.13.walk ibm_db_fetch_array (?)
    SQLGetData.621559.1441829876.13.walk ibm_db_fetch_array (?)
    SQLFetch.621559.1441829876.13.walk ibm_db_fetch_array (?)
    SQLGetData.621559.1441829876.13.walk ibm_db_fetch_array (?)
    SQLGetData.621559.1441829876.13.walk ibm_db_fetch_array (?)
    SQLGetData.621559.1441829876.13.walk ibm_db_fetch_array (?)
    SQLGetData.621559.1441829876.13.walk ibm_db_fetch_array (?)
    SQLGetData.621559.1441829876.13.walk ibm_db_fetch_array (?)
    SQLFetch.621559.1441829876.13.walk ibm_db_fetch_array (?)
    SQLFreeHandle.621559.1441829876.13.walk ibm_db_free_stmt (?)
    SQLFreeHandle.621559.1441829876.13.parm SQLSMALLINT htype 0x3 (3)
    SQLDisconnect.621559.1441829877.13.walk ibm_db_close (?)
    SQLFreeHandle.621559.1441829877.13.walk ibm_db_close (?)
    SQLFreeHandle.621559.1441829877.13.walk ibm_db_close (?)
    
    SQLAllocEnv.621559.1441829877.13.walk ibm_db_connect (?)
    SQLGetEnvAttr.621559.1441829877.13.walk ibm_db_connect (?)
    SQLGetEnvAttr.621559.1441829877.13.walk ibm_db_connect (?)
    SQLSetEnvAttr.621559.1441829877.13.walk ibm_db_connect (?)
    SQLAllocHandle.621559.1441829877.13.walk ibm_db_connect (?)
    SQLSetConnectAttr.621559.1441829877.13.walk ibm_db_connect (?)
    SQLConnect.621559.1441829877.13.walk ibm_db_connect (?)
    SQLGetConnectAttr.621559.1441829877.13.walk ibm_db_connect (?)
    SQLGetInfo.621559.1441829877.13.walk ibm_db_connect (?)
    SQLAllocHandle.621559.1441829877.13.walk ibm_db_exec (?)
    SQLAllocHandle.621559.1441829877.13.parm SQLSMALLINT htype 0x3 (3)
    SQLExecDirect.621559.1441829877.13.walk ibm_db_exec (?)
    SQLExecDirect.621559.1441829877.13.parm SQLHSTMT hstmt 0x3 (3)
    SQLDisconnect.621559.1441829877.13.walk ibm_db_close (?)
    SQLFreeHandle.621559.1441829877.13.walk ibm_db_close (?)
    SQLFreeHandle.621559.1441829877.13.walk ibm_db_close (?)
    
    SQLAllocEnv.621559.1441829877.13.walk ibm_db_connect (?)
    SQLGetEnvAttr.621559.1441829877.13.walk ibm_db_connect (?)
    SQLGetEnvAttr.621559.1441829877.13.walk ibm_db_connect (?)
    SQLSetEnvAttr.621559.1441829877.13.walk ibm_db_connect (?)
    SQLAllocHandle.621559.1441829877.13.walk ibm_db_connect (?)
    SQLSetConnectAttr.621559.1441829877.13.walk ibm_db_connect (?)
    SQLConnect.621559.1441829877.13.walk ibm_db_connect (?)
    SQLGetConnectAttr.621559.1441829877.13.walk ibm_db_connect (?)
    SQLGetInfo.621559.1441829877.13.walk ibm_db_connect (?)
    SQLAllocHandle.621559.1441829877.13.walk ibm_db_exec (?)
    SQLAllocHandle.621559.1441829877.13.parm SQLSMALLINT htype 0x3 (3)
    SQLExecDirect.621559.1441829877.13.walk ibm_db_exec (?)
    SQLExecDirect.621559.1441829877.13.parm SQLHSTMT hstmt 0x3 (3)
    SQLFreeHandle.621559.1441829877.14.walk gc_finalize_deferred (?)
    SQLFreeHandle.621559.1441829877.14.parm SQLSMALLINT htype 0x3 (3)
    SQLFreeHandle.621559.1441829877.14.parm SQLINTEGER hndl 0x3 (3)
    SQLFreeHandle.621559.1441829877.14.walk gc_finalize_deferred (?)
    SQLFreeHandle.621559.1441829877.14.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR)
    SQLFreeHandle.621559.1441829877.14.parm SQLSMALLINT htype 0x3 (3)
    SQLFreeHandle.621559.1441829877.14.parm SQLINTEGER hndl 0x3 (3)
    SQLDisconnect.621559.1441829877.14.walk ibm_db_close (?)
    SQLFreeHandle.621559.1441829877.14.walk ibm_db_close (?)
    SQLFreeHandle.621559.1441829877.14.walk ibm_db_close (?)
    
    SQLAllocEnv.621559.1441829877.14.walk ibm_db_connect (?)
    SQLGetEnvAttr.621559.1441829877.14.walk ibm_db_connect (?)
    SQLGetEnvAttr.621559.1441829877.14.walk ibm_db_connect (?)
    SQLSetEnvAttr.621559.1441829877.14.walk ibm_db_connect (?)
    SQLAllocHandle.621559.1441829877.14.walk ibm_db_connect (?)
    SQLSetConnectAttr.621559.1441829877.14.walk ibm_db_connect (?)
    SQLConnect.621559.1441829877.14.walk ibm_db_connect (?)
    SQLGetConnectAttr.621559.1441829877.14.walk ibm_db_connect (?)
    SQLGetInfo.621559.1441829877.14.walk ibm_db_connect (?)
    SQLAllocHandle.621559.1441829877.14.walk ibm_db_exec (?)
    SQLAllocHandle.621559.1441829877.14.parm SQLSMALLINT htype 0x3 (3)
    SQLExecDirect.621559.1441829877.14.walk ibm_db_exec (?)
    SQLExecDirect.621559.1441829877.14.parm SQLHSTMT hstmt 0x3 (3)
    SQLDisconnect.621559.1441829877.15.walk ibm_db_close (?)
    SQLFreeHandle.621559.1441829877.15.walk ibm_db_close (?)
    SQLFreeHandle.621559.1441829877.15.walk ibm_db_close (?)
    
    SQLAllocEnv.621559.1441829877.15.walk ibm_db_connect (?)
    SQLGetEnvAttr.621559.1441829877.15.walk ibm_db_connect (?)
    SQLGetEnvAttr.621559.1441829877.15.walk ibm_db_connect (?)
    SQLSetEnvAttr.621559.1441829877.15.walk ibm_db_connect (?)
    SQLAllocHandle.621559.1441829877.15.walk ibm_db_connect (?)
    SQLSetConnectAttr.621559.1441829877.15.walk ibm_db_connect (?)
    SQLConnect.621559.1441829877.15.walk ibm_db_connect (?)
    SQLGetConnectAttr.621559.1441829877.15.walk ibm_db_connect (?)
    SQLGetInfo.621559.1441829877.15.walk ibm_db_connect (?)
    SQLAllocHandle.621559.1441829877.15.walk ibm_db_exec (?)
    SQLAllocHandle.621559.1441829877.15.parm SQLSMALLINT htype 0x3 (3)
    SQLExecDirect.621559.1441829877.15.walk ibm_db_exec (?)
    SQLExecDirect.621559.1441829877.15.parm SQLHSTMT hstmt 0x3 (3)
    SQLDisconnect.621559.1441829877.16.walk ibm_db_close (?)
    SQLFreeHandle.621559.1441829877.16.walk ibm_db_close (?)
    SQLFreeHandle.621559.1441829877.16.walk ibm_db_close (?)
    
    SQLAllocEnv.621559.1441829877.16.walk ibm_db_connect (?)
    SQLGetEnvAttr.621559.1441829877.16.walk ibm_db_connect (?)
    SQLGetEnvAttr.621559.1441829877.16.walk ibm_db_connect (?)
    SQLSetEnvAttr.621559.1441829877.16.walk ibm_db_connect (?)
    SQLAllocHandle.621559.1441829877.16.walk ibm_db_connect (?)
    SQLSetConnectAttr.621559.1441829877.16.walk ibm_db_connect (?)
    SQLConnect.621559.1441829877.16.walk ibm_db_connect (?)
    SQLGetConnectAttr.621559.1441829877.16.walk ibm_db_connect (?)
    SQLGetInfo.621559.1441829877.16.walk ibm_db_connect (?)
    SQLAllocHandle.621559.1441829877.16.walk ibm_db_exec (?)
    SQLAllocHandle.621559.1441829877.16.parm SQLSMALLINT htype 0x3 (3)
    SQLExecDirect.621559.1441829877.16.walk ibm_db_exec (?)
    SQLExecDirect.621559.1441829877.16.parm SQLHSTMT hstmt 0x3 (3)
    SQLDisconnect.621559.1441829877.17.walk ibm_db_close (?)
    SQLFreeHandle.621559.1441829877.17.walk ibm_db_close (?)
    SQLFreeHandle.621559.1441829877.17.walk ibm_db_close (?)
    
    SQLAllocEnv.621559.1441829877.17.walk ibm_db_connect (?)
    SQLGetEnvAttr.621559.1441829877.17.walk ibm_db_connect (?)
    SQLGetEnvAttr.621559.1441829877.17.walk ibm_db_connect (?)
    SQLSetEnvAttr.621559.1441829877.17.walk ibm_db_connect (?)
    SQLAllocHandle.621559.1441829877.17.walk ibm_db_connect (?)
    SQLSetConnectAttr.621559.1441829877.17.walk ibm_db_connect (?)
    SQLConnect.621559.1441829877.17.walk ibm_db_connect (?)
    SQLGetConnectAttr.621559.1441829877.17.walk ibm_db_connect (?)
    SQLGetInfo.621559.1441829877.17.walk ibm_db_connect (?)
    SQLAllocHandle.621559.1441829877.17.walk ibm_db_exec (?)
    SQLAllocHandle.621559.1441829877.17.parm SQLSMALLINT htype 0x3 (3)
    SQLExecDirect.621559.1441829877.17.walk ibm_db_exec (?)
    SQLExecDirect.621559.1441829877.17.parm SQLHSTMT hstmt 0x3 (3)
    SQLDisconnect.621559.1441829877.18.walk ibm_db_close (?)
    SQLFreeHandle.621559.1441829877.18.walk ibm_db_close (?)
    SQLFreeHandle.621559.1441829877.18.walk ibm_db_close (?)
    
    SQLAllocEnv.621559.1441829877.18.walk ibm_db_connect (?)
    SQLGetEnvAttr.621559.1441829877.18.walk ibm_db_connect (?)
    SQLGetEnvAttr.621559.1441829877.18.walk ibm_db_connect (?)
    SQLSetEnvAttr.621559.1441829877.18.walk ibm_db_connect (?)
    SQLAllocHandle.621559.1441829877.18.walk ibm_db_connect (?)
    SQLSetConnectAttr.621559.1441829877.18.walk ibm_db_connect (?)
    SQLConnect.621559.1441829877.18.walk ibm_db_connect (?)
    SQLGetConnectAttr.621559.1441829877.18.walk ibm_db_connect (?)
    SQLGetInfo.621559.1441829877.18.walk ibm_db_connect (?)
    SQLAllocHandle.621559.1441829877.18.walk ibm_db_exec (?)
    SQLAllocHandle.621559.1441829877.18.parm SQLSMALLINT htype 0x3 (3)
    SQLExecDirect.621559.1441829877.18.walk ibm_db_exec (?)
    SQLExecDirect.621559.1441829877.18.parm SQLHSTMT hstmt 0x3 (3)
    SQLDisconnect.621559.1441829877.13.walk ibm_db_close (?)
    SQLFreeHandle.621559.1441829877.13.walk ibm_db_close (?)
    SQLFreeHandle.621559.1441829877.13.walk ibm_db_close (?)
    
    SQLAllocEnv.621559.1441829877.13.walk ibm_db_connect (?)
    SQLGetEnvAttr.621559.1441829877.13.walk ibm_db_connect (?)
    SQLGetEnvAttr.621559.1441829877.13.walk ibm_db_connect (?)
    SQLSetEnvAttr.621559.1441829877.13.walk ibm_db_connect (?)
    SQLAllocHandle.621559.1441829877.13.walk ibm_db_connect (?)
    SQLSetConnectAttr.621559.1441829877.13.walk ibm_db_connect (?)
    SQLConnect.621559.1441829877.13.walk ibm_db_connect (?)
    SQLGetConnectAttr.621559.1441829877.13.walk ibm_db_connect (?)
    SQLGetInfo.621559.1441829877.13.walk ibm_db_connect (?)
    SQLAllocHandle.621559.1441829877.13.walk ibm_db_exec (?)
    SQLAllocHandle.621559.1441829877.13.parm SQLSMALLINT htype 0x3 (3)
    SQLExecDirect.621559.1441829877.13.walk ibm_db_exec (?)
    SQLExecDirect.621559.1441829877.13.parm SQLHSTMT hstmt 0x3 (3)
    SQLDisconnect.621559.1441829897.19.walk ibm_db_close (?)
    SQLFreeHandle.621559.1441829897.19.walk ibm_db_close (?)
    SQLFreeHandle.621559.1441829897.19.walk ibm_db_close (?)
    
    SQLAllocEnv.621559.1441829897.19.walk ibm_db_connect (?)
    SQLGetEnvAttr.621559.1441829897.19.walk ibm_db_connect (?)
    SQLGetEnvAttr.621559.1441829897.19.walk ibm_db_connect (?)
    SQLSetEnvAttr.621559.1441829897.19.walk ibm_db_connect (?)
    SQLAllocHandle.621559.1441829897.19.walk ibm_db_connect (?)
    SQLSetConnectAttr.621559.1441829897.19.walk ibm_db_connect (?)
    SQLConnect.621559.1441829897.19.walk ibm_db_connect (?)
    SQLGetConnectAttr.621559.1441829897.19.walk ibm_db_connect (?)
    SQLGetInfo.621559.1441829897.19.walk ibm_db_connect (?)
    SQLAllocHandle.621559.1441829897.19.walk ibm_db_exec (?)
    SQLAllocHandle.621559.1441829897.19.parm SQLSMALLINT htype 0x3 (3)
    SQLExecDirect.621559.1441829897.19.walk ibm_db_exec (?)
    SQLExecDirect.621559.1441829897.19.parm SQLHSTMT hstmt 0x3 (3)
    SQLAllocHandle.621559.1441829897.19.walk ibm_db_exec (?)
    SQLAllocHandle.621559.1441829897.19.parm SQLSMALLINT htype 0x3 (3)
    SQLExecDirect.621559.1441829897.19.walk ibm_db_exec (?)
    SQLNumResultCols.621559.1441829897.19.walk ibm_db_result_cols (?)
    SQLBindCol.621559.1441829897.19.walk ibm_db_fetch_array (?)
    SQLBindCol.621559.1441829897.19.walk ibm_db_fetch_array (?)
    SQLBindCol.621559.1441829897.19.walk ibm_db_fetch_array (?)
    SQLFetch.621559.1441829897.19.walk ibm_db_fetch_array (?)
    SQLGetData.621559.1441829897.19.walk ibm_db_fetch_array (?)
    SQLGetData.621559.1441829897.19.walk ibm_db_fetch_array (?)
    SQLGetData.621559.1441829897.19.walk ibm_db_fetch_array (?)
    SQLGetData.621559.1441829897.19.walk ibm_db_fetch_array (?)
    SQLGetData.621559.1441829897.19.walk ibm_db_fetch_array (?)
    SQLFetch.621559.1441829897.19.walk ibm_db_fetch_array (?)
    SQLGetData.621559.1441829897.19.walk ibm_db_fetch_array (?)
    SQLGetData.621559.1441829897.19.walk ibm_db_fetch_array (?)
    SQLGetData.621559.1441829897.19.walk ibm_db_fetch_array (?)
    SQLGetData.621559.1441829897.19.walk ibm_db_fetch_array (?)
    SQLGetData.621559.1441829897.19.walk ibm_db_fetch_array (?)
    SQLFetch.621559.1441829897.19.walk ibm_db_fetch_array (?)
    SQLFreeHandle.621559.1441829897.19.walk ibm_db_free_stmt (?)
    SQLFreeHandle.621559.1441829897.19.parm SQLSMALLINT htype 0x3 (3)
    SQLFreeHandle.621559.1441829897.19.parm SQLSMALLINT htype 0x3 (3)
    SQLFreeHandle.621559.1441829897.19.parm SQLINTEGER hndl 0x3 (3)
    SQLFreeHandle.621559.1441829897.19.walk gc_finalize_deferred (?)
    SQLFreeHandle.621559.1441829897.19.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR)
    SQLFreeHandle.621559.1441829897.19.parm SQLSMALLINT htype 0x3 (3)
    SQLFreeHandle.621559.1441829897.19.parm SQLINTEGER hndl 0x3 (3)
    SQLFreeHandle.621559.1441829897.19.walk gc_finalize_deferred (?)
    SQLFreeHandle.621559.1441829897.19.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR)
    SQLFreeHandle.621559.1441829897.19.parm SQLSMALLINT htype 0x3 (3)
    SQLFreeHandle.621559.1441829897.19.parm SQLINTEGER hndl 0x3 (3)
    SQLFreeHandle.621559.1441829897.19.walk gc_finalize_deferred (?)
    SQLFreeHandle.621559.1441829897.19.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR)
    SQLFreeHandle.621559.1441829897.19.parm SQLSMALLINT htype 0x3 (3)
    SQLFreeHandle.621559.1441829897.19.parm SQLINTEGER hndl 0x3 (3)
    SQLFreeHandle.621559.1441829897.19.walk gc_finalize_deferred (?)
    SQLFreeHandle.621559.1441829897.19.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR)
    SQLFreeHandle.621559.1441829897.19.parm SQLSMALLINT htype 0x3 (3)
    SQLFreeHandle.621559.1441829897.19.parm SQLINTEGER hndl 0x3 (3)
    SQLFreeHandle.621559.1441829897.19.walk gc_finalize_deferred (?)
    SQLFreeHandle.621559.1441829897.19.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR)
    SQLFreeHandle.621559.1441829897.19.parm SQLSMALLINT htype 0x3 (3)
    SQLFreeHandle.621559.1441829897.19.parm SQLINTEGER hndl 0x3 (3)
    SQLFreeHandle.621559.1441829897.19.walk gc_finalize_deferred (?)
    SQLFreeHandle.621559.1441829897.19.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR)
    SQLFreeHandle.621559.1441829897.19.parm SQLSMALLINT htype 0x3 (3)
    SQLFreeHandle.621559.1441829897.19.parm SQLINTEGER hndl 0x3 (3)
    SQLDisconnect.621559.1441829897.19.walk ibm_db_close (?)
    SQLFreeHandle.621559.1441829897.19.walk ibm_db_close (?)
    SQLFreeHandle.621559.1441829897.19.walk ibm_db_close (?)
    
    SQLAllocEnv.621559.1441829897.19.walk ibm_db_connect (?)
    SQLGetEnvAttr.621559.1441829897.19.walk ibm_db_connect (?)
    SQLGetEnvAttr.621559.1441829897.19.walk ibm_db_connect (?)
    SQLSetEnvAttr.621559.1441829897.19.walk ibm_db_connect (?)
    SQLAllocHandle.621559.1441829897.19.walk ibm_db_connect (?)
    SQLSetConnectAttr.621559.1441829897.19.walk ibm_db_connect (?)
    SQLFreeHandle.621559.1441829897.19.walk gc_finalize_deferred (?)
    SQLFreeHandle.621559.1441829897.19.walk ibm_db_connect (?)
    SQLFreeHandle.621559.1441829897.19.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR)
    SQLFreeHandle.621559.1441829897.19.parm SQLSMALLINT htype 0x3 (3)
    SQLFreeHandle.621559.1441829897.19.parm SQLINTEGER hndl 0x3 (3)
    SQLConnect.621559.1441829897.19.walk ibm_db_connect (?)
    SQLGetConnectAttr.621559.1441829897.19.walk ibm_db_connect (?)
    SQLGetInfo.621559.1441829897.19.walk ibm_db_connect (?)
    SQLAllocHandle.621559.1441829897.19.walk ibm_db_exec (?)
    SQLAllocHandle.621559.1441829897.19.parm SQLSMALLINT htype 0x3 (3)
    SQLExecDirect.621559.1441829897.19.walk ibm_db_exec (?)
    SQLExecDirect.621559.1441829897.19.parm SQLHSTMT hstmt 0x3 (3)
    SQLDisconnect.621559.1441829897.20.walk ibm_db_close (?)
    SQLFreeHandle.621559.1441829897.20.walk ibm_db_close (?)
    SQLFreeHandle.621559.1441829897.20.walk ibm_db_close (?)
    
    SQLAllocEnv.621559.1441829897.20.walk ibm_db_connect (?)
    SQLGetEnvAttr.621559.1441829897.20.walk ibm_db_connect (?)
    SQLGetEnvAttr.621559.1441829897.20.walk ibm_db_connect (?)
    SQLSetEnvAttr.621559.1441829897.20.walk ibm_db_connect (?)
    SQLAllocHandle.621559.1441829897.20.walk ibm_db_connect (?)
    SQLSetConnectAttr.621559.1441829897.20.walk ibm_db_connect (?)
    SQLConnect.621559.1441829897.20.walk ibm_db_connect (?)
    SQLGetConnectAttr.621559.1441829897.20.walk ibm_db_connect (?)
    SQLGetInfo.621559.1441829897.20.walk ibm_db_connect (?)
    SQLAllocHandle.621559.1441829897.20.walk ibm_db_exec (?)
    SQLAllocHandle.621559.1441829897.20.parm SQLSMALLINT htype 0x3 (3)
    SQLExecDirect.621559.1441829897.20.walk ibm_db_exec (?)
    SQLExecDirect.621559.1441829897.20.parm SQLHSTMT hstmt 0x3 (3)
    SQLFreeHandle.621559.1441829897.21.walk gc_finalize_deferred (?)
    SQLFreeHandle.621559.1441829897.21.parm SQLSMALLINT htype 0x3 (3)
    SQLFreeHandle.621559.1441829897.21.parm SQLINTEGER hndl 0x3 (3)
    SQLDisconnect.621559.1441829897.21.walk ibm_db_close (?)
    SQLFreeHandle.621559.1441829897.21.walk ibm_db_close (?)
    SQLFreeHandle.621559.1441829897.21.walk ibm_db_close (?)
    
    SQLAllocEnv.621559.1441829897.21.walk ibm_db_connect (?)
    SQLGetEnvAttr.621559.1441829897.21.walk ibm_db_connect (?)
    SQLGetEnvAttr.621559.1441829897.21.walk ibm_db_connect (?)
    SQLSetEnvAttr.621559.1441829897.21.walk ibm_db_connect (?)
    SQLAllocHandle.621559.1441829897.21.walk ibm_db_connect (?)
    SQLSetConnectAttr.621559.1441829897.21.walk ibm_db_connect (?)
    SQLConnect.621559.1441829897.21.walk ibm_db_connect (?)
    SQLGetConnectAttr.621559.1441829897.21.walk ibm_db_connect (?)
    SQLGetInfo.621559.1441829897.21.walk ibm_db_connect (?)
    SQLAllocHandle.621559.1441829897.21.walk ibm_db_exec (?)
    SQLAllocHandle.621559.1441829897.21.parm SQLSMALLINT htype 0x3 (3)
    SQLExecDirect.621559.1441829897.21.walk ibm_db_exec (?)
    SQLExecDirect.621559.1441829897.21.parm SQLHSTMT hstmt 0x3 (3)
    SQLDisconnect.621559.1441829897.22.walk ibm_db_close (?)
    SQLFreeHandle.621559.1441829897.22.walk ibm_db_close (?)
    SQLFreeHandle.621559.1441829897.22.walk ibm_db_close (?)
    
    SQLAllocEnv.621559.1441829897.22.walk ibm_db_connect (?)
    SQLGetEnvAttr.621559.1441829897.22.walk ibm_db_connect (?)
    SQLGetEnvAttr.621559.1441829897.22.walk ibm_db_connect (?)
    SQLSetEnvAttr.621559.1441829897.22.walk ibm_db_connect (?)
    SQLAllocHandle.621559.1441829897.22.walk ibm_db_connect (?)
    SQLSetConnectAttr.621559.1441829897.22.walk ibm_db_connect (?)
    SQLConnect.621559.1441829897.22.walk ibm_db_connect (?)
    SQLGetConnectAttr.621559.1441829897.22.walk ibm_db_connect (?)
    SQLGetInfo.621559.1441829897.22.walk ibm_db_connect (?)
    SQLAllocHandle.621559.1441829897.22.walk ibm_db_exec (?)
    SQLAllocHandle.621559.1441829897.22.parm SQLSMALLINT htype 0x3 (3)
    SQLExecDirect.621559.1441829897.22.walk ibm_db_exec (?)
    SQLExecDirect.621559.1441829897.22.parm SQLHSTMT hstmt 0x3 (3)
    SQLDisconnect.621559.1441829897.19.walk ibm_db_close (?)
    SQLFreeHandle.621559.1441829897.19.walk ibm_db_close (?)
    SQLFreeHandle.621559.1441829897.19.walk ibm_db_close (?)
    
    SQLAllocEnv.621559.1441829897.19.walk ibm_db_connect (?)
    SQLGetEnvAttr.621559.1441829897.19.walk ibm_db_connect (?)
    SQLGetEnvAttr.621559.1441829897.19.walk ibm_db_connect (?)
    SQLSetEnvAttr.621559.1441829897.19.walk ibm_db_connect (?)
    SQLAllocHandle.621559.1441829897.19.walk ibm_db_connect (?)
    SQLSetConnectAttr.621559.1441829897.19.walk ibm_db_connect (?)
    SQLConnect.621559.1441829897.19.walk ibm_db_connect (?)
    SQLGetConnectAttr.621559.1441829897.19.walk ibm_db_connect (?)
    SQLGetInfo.621559.1441829897.19.walk ibm_db_connect (?)
    SQLAllocHandle.621559.1441829897.19.walk ibm_db_exec (?)
    SQLAllocHandle.621559.1441829897.19.parm SQLSMALLINT htype 0x3 (3)
    SQLExecDirect.621559.1441829897.19.walk ibm_db_exec (?)
    SQLExecDirect.621559.1441829897.19.parm SQLHSTMT hstmt 0x3 (3)
    SQLDisconnect.621559.1441829897.20.walk ibm_db_close (?)
    SQLFreeHandle.621559.1441829897.20.walk ibm_db_close (?)
    SQLFreeHandle.621559.1441829897.20.walk ibm_db_close (?)
    
    SQLAllocEnv.621559.1441829897.20.walk ibm_db_connect (?)
    SQLGetEnvAttr.621559.1441829897.20.walk ibm_db_connect (?)
    SQLGetEnvAttr.621559.1441829897.20.walk ibm_db_connect (?)
    SQLSetEnvAttr.621559.1441829897.20.walk ibm_db_connect (?)
    SQLAllocHandle.621559.1441829897.20.walk ibm_db_connect (?)
    SQLSetConnectAttr.621559.1441829897.20.walk ibm_db_connect (?)
    SQLConnect.621559.1441829897.20.walk ibm_db_connect (?)
    SQLGetConnectAttr.621559.1441829897.20.walk ibm_db_connect (?)
    SQLGetInfo.621559.1441829897.20.walk ibm_db_connect (?)
    SQLAllocHandle.621559.1441829897.20.walk ibm_db_exec (?)
    SQLAllocHandle.621559.1441829897.20.parm SQLSMALLINT htype 0x3 (3)
    SQLExecDirect.621559.1441829897.20.walk ibm_db_exec (?)
    SQLExecDirect.621559.1441829897.20.parm SQLHSTMT hstmt 0x3 (3)
    SQLDisconnect.621559.1441829897.21.walk ibm_db_close (?)
    SQLFreeHandle.621559.1441829897.21.walk ibm_db_close (?)
    SQLFreeHandle.621559.1441829897.21.walk ibm_db_close (?)
    
    SQLAllocEnv.621559.1441829897.21.walk ibm_db_connect (?)
    SQLGetEnvAttr.621559.1441829897.21.walk ibm_db_connect (?)
    SQLGetEnvAttr.621559.1441829897.21.walk ibm_db_connect (?)
    SQLSetEnvAttr.621559.1441829897.21.walk ibm_db_connect (?)
    SQLAllocHandle.621559.1441829897.21.walk ibm_db_connect (?)
    SQLSetConnectAttr.621559.1441829897.21.walk ibm_db_connect (?)
    SQLConnect.621559.1441829897.21.walk ibm_db_connect (?)
    SQLGetConnectAttr.621559.1441829897.21.walk ibm_db_connect (?)
    SQLGetInfo.621559.1441829897.21.walk ibm_db_connect (?)
    SQLAllocHandle.621559.1441829897.21.walk ibm_db_exec (?)
    SQLAllocHandle.621559.1441829897.21.parm SQLSMALLINT htype 0x3 (3)
    SQLExecDirect.621559.1441829897.21.walk ibm_db_exec (?)
    SQLExecDirect.621559.1441829897.21.parm SQLHSTMT hstmt 0x3 (3)
    SQLDisconnect.621559.1441829898.22.walk ibm_db_close (?)
    SQLFreeHandle.621559.1441829898.22.walk ibm_db_close (?)
    SQLFreeHandle.621559.1441829898.22.walk ibm_db_close (?)
    
    SQLAllocEnv.621559.1441829898.22.walk ibm_db_connect (?)
    SQLGetEnvAttr.621559.1441829898.22.walk ibm_db_connect (?)
    SQLGetEnvAttr.621559.1441829898.22.walk ibm_db_connect (?)
    SQLSetEnvAttr.621559.1441829898.22.walk ibm_db_connect (?)
    SQLAllocHandle.621559.1441829898.22.walk ibm_db_connect (?)
    SQLSetConnectAttr.621559.1441829898.22.walk ibm_db_connect (?)
    SQLConnect.621559.1441829898.22.walk ibm_db_connect (?)
    SQLGetConnectAttr.621559.1441829898.22.walk ibm_db_connect (?)
    SQLGetInfo.621559.1441829898.22.walk ibm_db_connect (?)
    SQLAllocHandle.621559.1441829898.22.walk ibm_db_exec (?)
    SQLAllocHandle.621559.1441829898.22.parm SQLSMALLINT htype 0x3 (3)
    SQLExecDirect.621559.1441829898.22.walk ibm_db_exec (?)
    SQLExecDirect.621559.1441829898.22.parm SQLHSTMT hstmt 0x3 (3)
    [adc@oc7083008330 aaron-2015-06-24]$ 
    
  72. Former user Account Deleted

    Yes, they are aware of the problem and monitoring this thread

    Wait a minute, you did not really answer the question.

    Does this customer, see this issue, using the same version Ruby that i am using (older version)???

    This is not the time for political correct, we have to know the difference between "i thought i heard about a issue", and, "i bloody well have this issue".

    Do you understand?

  73. Aaron Bartell reporter

    Sorry, yes, customer has this issue. I have access to their machine and can reproduce the error on their machine. So this is a "I bloody well have this issue". Actually, I've verified this error on multiple customer machines that have the same version you have (PowerRuby v1.0.7)

    Again let me know if you want to get access to a machine (Litmis Spaces) where this error can be reproduced so you can see the error first hand.

  74. Former user Account Deleted

    Sorry, cut/paste wrong data (issue is still same) ...

    SQLAllocEnv.638756.1441906534.69.walk ibm_db_connect (?)
    SQLGetEnvAttr.638756.1441906534.69.walk ibm_db_connect (?)
    SQLGetEnvAttr.638756.1441906534.69.walk ibm_db_connect (?)
    SQLSetEnvAttr.638756.1441906534.69.walk ibm_db_connect (?)
    SQLAllocHandle.638756.1441906534.69.walk ibm_db_connect (?)
    SQLSetConnectAttr.638756.1441906534.69.walk ibm_db_connect (?)
    SQLConnect.638756.1441906534.69.walk ibm_db_connect (?)
    SQLGetConnectAttr.638756.1441906534.69.walk ibm_db_connect (?)
    SQLGetInfo.638756.1441906534.69.walk ibm_db_connect (?)
    SQLAllocHandle.638756.1441906534.69.walk ibm_db_exec (?)
    SQLAllocHandle.638756.1441906534.69.parm SQLSMALLINT htype 0x3 (3)
    SQLExecDirect.638756.1441906534.69.walk ibm_db_exec (?)
    SQLExecDirect.638756.1441906534.69.parm SQLHSTMT hstmt 0x3 (3)
    SQLFreeHandle.638756.1441906534.69.walk gc_finalize_deferred (?)
    SQLFreeHandle.638756.1441906534.69.parm SQLSMALLINT htype 0x3 (3)
    SQLFreeHandle.638756.1441906534.69.parm SQLINTEGER hndl 0x3 (3)
    SQLDisconnect.638756.1441906534.68.walk ibm_db_close (?)
    SQLFreeHandle.638756.1441906534.68.walk ibm_db_close (?)
    SQLFreeHandle.638756.1441906534.68.walk ibm_db_close (?)
    
    SQLAllocEnv.638756.1441906534.68.walk ibm_db_connect (?)
    SQLGetEnvAttr.638756.1441906534.68.walk ibm_db_connect (?)
    SQLGetEnvAttr.638756.1441906534.68.walk ibm_db_connect (?)
    SQLSetEnvAttr.638756.1441906534.68.walk ibm_db_connect (?)
    SQLAllocHandle.638756.1441906534.68.walk ibm_db_connect (?)
    SQLSetConnectAttr.638756.1441906534.68.walk ibm_db_connect (?)
    SQLConnect.638756.1441906534.68.walk ibm_db_connect (?)
    SQLGetConnectAttr.638756.1441906534.68.walk ibm_db_connect (?)
    SQLGetInfo.638756.1441906534.68.walk ibm_db_connect (?)
    SQLAllocHandle.638756.1441906534.68.walk ibm_db_exec (?)
    SQLAllocHandle.638756.1441906534.68.parm SQLSMALLINT htype 0x3 (3)
    SQLExecDirect.638756.1441906534.68.walk ibm_db_exec (?)
    SQLExecDirect.638756.1441906534.68.parm SQLHSTMT hstmt 0x3 (3)
    SQLFreeHandle.638756.1441906534.68.walk gc_finalize_deferred (?)
    SQLFreeHandle.638756.1441906534.68.parm SQLSMALLINT htype 0x3 (3)
    SQLFreeHandle.638756.1441906534.68.parm SQLINTEGER hndl 0x3 (3)
    SQLFreeHandle.638756.1441906534.68.walk gc_finalize_deferred (?)
    SQLFreeHandle.638756.1441906534.68.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR)
    SQLFreeHandle.638756.1441906534.68.parm SQLSMALLINT htype 0x3 (3)
    SQLFreeHandle.638756.1441906534.68.parm SQLINTEGER hndl 0x3 (3)
    SQLDisconnect.638756.1441906534.71.walk ibm_db_close (?)
    SQLFreeHandle.638756.1441906534.71.walk ibm_db_close (?)
    SQLFreeHandle.638756.1441906534.71.walk ibm_db_close (?)
    
    SQLAllocEnv.638756.1441906534.71.walk ibm_db_connect (?)
    SQLGetEnvAttr.638756.1441906534.71.walk ibm_db_connect (?)
    SQLGetEnvAttr.638756.1441906534.71.walk ibm_db_connect (?)
    SQLSetEnvAttr.638756.1441906534.71.walk ibm_db_connect (?)
    SQLAllocHandle.638756.1441906534.71.walk ibm_db_connect (?)
    SQLSetConnectAttr.638756.1441906534.71.walk ibm_db_connect (?)
    SQLConnect.638756.1441906534.71.walk ibm_db_connect (?)
    SQLGetConnectAttr.638756.1441906534.71.walk ibm_db_connect (?)
    SQLGetInfo.638756.1441906534.71.walk ibm_db_connect (?)
    SQLAllocHandle.638756.1441906534.71.walk ibm_db_exec (?)
    SQLAllocHandle.638756.1441906534.71.parm SQLSMALLINT htype 0x3 (3)
    SQLExecDirect.638756.1441906534.71.walk ibm_db_exec (?)
    SQLExecDirect.638756.1441906534.71.parm SQLHSTMT hstmt 0x3 (3)
    SQLFreeHandle.638756.1441906534.71.walk gc_finalize_deferred (?)
    SQLFreeHandle.638756.1441906534.71.parm SQLSMALLINT htype 0x3 (3)
    SQLFreeHandle.638756.1441906534.71.parm SQLINTEGER hndl 0x3 (3)
    SQLFreeHandle.638756.1441906535.73.walk gc_finalize_deferred (?)
    SQLFreeHandle.638756.1441906535.73.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR)
    SQLFreeHandle.638756.1441906535.73.parm SQLSMALLINT htype 0x3 (3)
    SQLFreeHandle.638756.1441906535.73.parm SQLINTEGER hndl 0x3 (3)
    SQLDisconnect.638756.1441906535.73.walk ibm_db_close (?)
    SQLFreeHandle.638756.1441906535.73.walk ibm_db_close (?)
    SQLFreeHandle.638756.1441906535.73.walk ibm_db_close (?)
    
    SQLAllocEnv.638756.1441906535.73.walk ibm_db_connect (?)
    SQLGetEnvAttr.638756.1441906535.73.walk ibm_db_connect (?)
    SQLGetEnvAttr.638756.1441906535.73.walk ibm_db_connect (?)
    SQLSetEnvAttr.638756.1441906535.73.walk ibm_db_connect (?)
    SQLAllocHandle.638756.1441906535.73.walk ibm_db_connect (?)
    SQLSetConnectAttr.638756.1441906535.73.walk ibm_db_connect (?)
    SQLConnect.638756.1441906535.73.walk ibm_db_connect (?)
    SQLGetConnectAttr.638756.1441906535.73.walk ibm_db_connect (?)
    SQLGetInfo.638756.1441906535.73.walk ibm_db_connect (?)
    SQLAllocHandle.638756.1441906535.73.walk ibm_db_exec (?)
    SQLAllocHandle.638756.1441906535.73.parm SQLSMALLINT htype 0x3 (3)
    SQLExecDirect.638756.1441906535.73.walk ibm_db_exec (?)
    SQLExecDirect.638756.1441906535.73.parm SQLHSTMT hstmt 0x3 (3)
    SQLFreeHandle.638756.1441906535.73.walk gc_finalize_deferred (?)
    SQLFreeHandle.638756.1441906535.73.parm SQLSMALLINT htype 0x3 (3)
    SQLFreeHandle.638756.1441906535.73.parm SQLINTEGER hndl 0x3 (3)
    SQLAllocHandle.638756.1441906535.73.walk ibm_db_exec (?)
    SQLAllocHandle.638756.1441906535.73.parm SQLSMALLINT htype 0x3 (3)
    SQLExecDirect.638756.1441906535.73.walk ibm_db_exec (?)
    SQLExecDirect.638756.1441906535.73.parm SQLHSTMT hstmt 0x3 (3)
    SQLFreeHandle.638756.1441906535.73.walk gc_finalize_deferred (?)
    SQLFreeHandle.638756.1441906535.73.parm SQLSMALLINT htype 0x3 (3)
    SQLFreeHandle.638756.1441906535.73.parm SQLINTEGER hndl 0x3 (3)
    SQLNumResultCols.638756.1441906535.73.walk ibm_db_result_cols (?)
    SQLNumResultCols.638756.1441906535.73.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR)
    SQLNumResultCols.638756.1441906535.73.parm SQLHSTMT hstmt 0x3 (3)
    SQLGetDiagRec.638756.1441906535.73.walk ibm_db_result_cols (?)
    SQLGetDiagRec.638756.1441906535.73.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR)
    SQLGetDiagRec.638756.1441906535.73.parm SQLINTEGER hndl 0x3 (3)
    SQLAllocHandle.638756.1441906535.73.walk ibm_db_exec (?)
    SQLAllocHandle.638756.1441906535.73.parm SQLSMALLINT htype 0x3 (3)
    SQLExecDirect.638756.1441906535.73.walk ibm_db_exec (?)
    SQLExecDirect.638756.1441906535.73.parm SQLHSTMT hstmt 0x3 (3)
    SQLNumResultCols.638756.1441906535.73.walk ibm_db_result_cols (?)
    SQLNumResultCols.638756.1441906535.73.parm SQLHSTMT hstmt 0x3 (3)
    SQLDescribeCol.638756.1441906535.73.parm SQLHSTMT hstmt 0x3 (3)
    SQLDescribeCol.638756.1441906535.73.parm SQLHSTMT hstmt 0x3 (3)
    SQLDescribeCol.638756.1441906535.73.parm SQLHSTMT hstmt 0x3 (3)
    SQLDescribeCol.638756.1441906535.73.parm SQLHSTMT hstmt 0x3 (3)
    SQLDescribeCol.638756.1441906535.73.parm SQLHSTMT hstmt 0x3 (3)
    SQLDescribeCol.638756.1441906535.73.parm SQLHSTMT hstmt 0x3 (3)
    SQLDescribeCol.638756.1441906535.73.parm SQLHSTMT hstmt 0x3 (3)
    SQLDescribeCol.638756.1441906535.73.parm SQLHSTMT hstmt 0x3 (3)
    SQLBindCol.638756.1441906535.73.walk ibm_db_fetch_array (?)
    SQLBindCol.638756.1441906535.73.parm SQLHSTMT hstmt 0x3 (3)
    SQLBindCol.638756.1441906535.73.walk ibm_db_fetch_array (?)
    SQLBindCol.638756.1441906535.73.parm SQLHSTMT hstmt 0x3 (3)
    SQLBindCol.638756.1441906535.73.walk ibm_db_fetch_array (?)
    SQLBindCol.638756.1441906535.73.parm SQLHSTMT hstmt 0x3 (3)
    SQLFetch.638756.1441906535.73.walk ibm_db_fetch_array (?)
    SQLFetch.638756.1441906535.73.parm SQLHSTMT hstmt 0x3 (3)
    SQLGetData.638756.1441906535.73.walk ibm_db_fetch_array (?)
    SQLGetData.638756.1441906535.73.parm SQLHSTMT hstmt 0x3 (3)
    SQLGetData.638756.1441906535.73.walk ibm_db_fetch_array (?)
    SQLGetData.638756.1441906535.73.parm SQLHSTMT hstmt 0x3 (3)
    SQLGetData.638756.1441906535.73.walk ibm_db_fetch_array (?)
    SQLGetData.638756.1441906535.73.parm SQLHSTMT hstmt 0x3 (3)
    SQLGetData.638756.1441906535.73.walk ibm_db_fetch_array (?)
    SQLGetData.638756.1441906535.73.parm SQLHSTMT hstmt 0x3 (3)
    SQLGetData.638756.1441906535.73.walk ibm_db_fetch_array (?)
    SQLGetData.638756.1441906535.73.parm SQLHSTMT hstmt 0x3 (3)
    SQLFetch.638756.1441906535.73.walk ibm_db_fetch_array (?)
    SQLFetch.638756.1441906535.73.parm SQLHSTMT hstmt 0x3 (3)
    SQLGetData.638756.1441906535.73.walk ibm_db_fetch_array (?)
    SQLGetData.638756.1441906535.73.parm SQLHSTMT hstmt 0x3 (3)
    SQLGetData.638756.1441906535.73.walk ibm_db_fetch_array (?)
    SQLGetData.638756.1441906535.73.parm SQLHSTMT hstmt 0x3 (3)
    SQLGetData.638756.1441906535.73.walk ibm_db_fetch_array (?)
    SQLGetData.638756.1441906535.73.parm SQLHSTMT hstmt 0x3 (3)
    SQLGetData.638756.1441906535.73.walk ibm_db_fetch_array (?)
    SQLGetData.638756.1441906535.73.parm SQLHSTMT hstmt 0x3 (3)
    SQLGetData.638756.1441906535.73.walk ibm_db_fetch_array (?)
    SQLGetData.638756.1441906535.73.parm SQLHSTMT hstmt 0x3 (3)
    SQLFetch.638756.1441906535.73.walk ibm_db_fetch_array (?)
    SQLFetch.638756.1441906535.73.parm SQLHSTMT hstmt 0x3 (3)
    SQLFreeHandle.638756.1441906535.73.walk ibm_db_free_stmt (?)
    SQLFreeHandle.638756.1441906535.73.parm SQLSMALLINT htype 0x3 (3)
    SQLFreeHandle.638756.1441906535.73.parm SQLINTEGER hndl 0x3 (3)
    SQLFreeHandle.638756.1441906535.73.walk gc_finalize_deferred (?)
    SQLFreeHandle.638756.1441906535.73.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR)
    SQLFreeHandle.638756.1441906535.73.parm SQLSMALLINT htype 0x3 (3)
    SQLFreeHandle.638756.1441906535.73.parm SQLINTEGER hndl 0x3 (3)
    SQLFreeHandle.638756.1441906535.73.walk gc_finalize_deferred (?)
    SQLFreeHandle.638756.1441906535.73.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR)
    SQLFreeHandle.638756.1441906535.73.parm SQLSMALLINT htype 0x3 (3)
    SQLFreeHandle.638756.1441906535.73.parm SQLINTEGER hndl 0x3 (3)
    SQLDisconnect.638756.1441906535.74.walk ibm_db_close (?)
    SQLFreeHandle.638756.1441906535.74.walk ibm_db_close (?)
    SQLFreeHandle.638756.1441906535.74.walk ibm_db_close (?)
    
  75. Former user Account Deleted

    Well, "first hand" is not my real objective. What we need is tooling, like our trace, that puts the "collecting of data" into the art of the possible, without jumping on every machine. However, trial case this, we are starting to see value of PASE side trace tool taking shape (DB2-side monitor/trace would never even get close).

  76. Former user Account Deleted

    BTW -- trace analysis, you can see fancy grep statement i am using to pull data from the trace ... i am on a Linux machine, so grep is probably more powerful than AIX or PASE (not 100% sure you can do).

    grep "hstmt 0x3\|hndl 0x3\|htype 0x3\|walk ibm\|walk gc\|SQL_ERROR" trace-2015-09-10-2.txt
    
  77. Aaron Bartell reporter

    Well, "first hand" is not my real objective.

    Fair enough. I do believe this thread will be visited often to learn the approach to deep PASE debugging (your greater intention). So now we need next steps ideas. One I can do is modify ibm_db_adapter.rb to have a TracePoint like I did for the trace:run rake task. This would give us method execution order from the Ruby side of things and might produce some "aha's".

    Do you agree this is a good next step?

  78. Former user Account Deleted

    Mmm ... maybe you see this ... but i am not sure i can synchronize/match trace log entries with rake trace. How would this be done?

    We know invalid handle occurred due to a Ruby script call ibm_db_result_cols, so maybe we can associate that way.

    SQLNumResultCols.638756.1441906535.73.tbeg ---error---
    SQLNumResultCols.638756.1441906535.73.walk dump_SQLNumResultCols (fffffffe 3 22888e54)
    SQLNumResultCols.638756.1441906535.73.walk SQLNumResultCols (3 22888e54)
    SQLNumResultCols.638756.1441906535.73.walk _ruby_ibm_db_SQLNumResultCols_helper (?)
    SQLNumResultCols.638756.1441906535.73.walk _ruby_ibm_db_get_result_set_info (?)
    SQLNumResultCols.638756.1441906535.73.walk ibm_db_result_cols (?)
    SQLNumResultCols.638756.1441906535.73.walk call_cfunc_m1 (?)
    SQLNumResultCols.638756.1441906535.73.walk vm_call_cfunc_with_frame (?)
    SQLNumResultCols.638756.1441906535.73.walk vm_exec_core (?)
    SQLNumResultCols.638756.1441906535.73.walk vm_exec (?)
    SQLNumResultCols.638756.1441906535.73.walk invoke_block_from_c (?)
    SQLNumResultCols.638756.1441906535.73.walk rb_yield (?)
    SQLNumResultCols.638756.1441906535.73.walk int_dotimes (?)
    SQLNumResultCols.638756.1441906535.73.walk call_cfunc_0 (?)
    SQLNumResultCols.638756.1441906535.73.walk vm_call_cfunc_with_frame (?)
    SQLNumResultCols.638756.1441906535.73.walk vm_exec_core (?)
    SQLNumResultCols.638756.1441906535.73.walk vm_exec (?)
    SQLNumResultCols.638756.1441906535.73.walk invoke_block_from_c (?)
    SQLNumResultCols.638756.1441906535.73.walk vm_invoke_proc (?)
    SQLNumResultCols.638756.1441906535.73.walk proc_call (?)
    SQLNumResultCols.638756.1441906535.73.walk call_cfunc_m1 (?)
    SQLNumResultCols.638756.1441906535.73.walk vm_call_cfunc_with_frame (?)
    SQLNumResultCols.638756.1441906535.73.walk vm_exec_core (?)
    SQLNumResultCols.638756.1441906535.73.walk vm_exec (?)
    SQLNumResultCols.638756.1441906535.73.walk invoke_block_from_c (?)
    SQLNumResultCols.638756.1441906535.73.walk vm_invoke_proc (?)
    SQLNumResultCols.638756.1441906535.73.walk proc_call (?)
    SQLNumResultCols.638756.1441906535.73.walk call_cfunc_m1 (?)
    SQLNumResultCols.638756.1441906535.73.walk vm_call_cfunc_with_frame (?)
    SQLNumResultCols.638756.1441906535.73.walk vm_exec_core (?)
    SQLNumResultCols.638756.1441906535.73.walk vm_exec (?)
    SQLNumResultCols.638756.1441906535.73.walk invoke_block_from_c (?)
    SQLNumResultCols.638756.1441906535.73.walk vm_invoke_proc (?)
    SQLNumResultCols.638756.1441906535.73.walk proc_call (?)
    SQLNumResultCols.638756.1441906535.73.walk call_cfunc_m1 (?)
    SQLNumResultCols.638756.1441906535.73.walk vm_call_cfunc_with_frame (?)
    SQLNumResultCols.638756.1441906535.73.walk vm_exec_core (?)
    SQLNumResultCols.638756.1441906535.73.walk vm_exec (?)
    SQLNumResultCols.638756.1441906535.73.walk invoke_block_from_c (?)
    SQLNumResultCols.638756.1441906535.73.walk vm_invoke_proc (?)
    SQLNumResultCols.638756.1441906535.73.walk proc_call (?)
    SQLNumResultCols.638756.1441906535.73.walk call_cfunc_m1 (?)
    SQLNumResultCols.638756.1441906535.73.walk vm_call_cfunc_with_frame (?)
    SQLNumResultCols.638756.1441906535.73.walk vm_exec_core (?)
    SQLNumResultCols.638756.1441906535.73.walk vm_exec (?)
    SQLNumResultCols.638756.1441906535.73.walk invoke_block_from_c (?)
    SQLNumResultCols.638756.1441906535.73.walk vm_invoke_proc (?)
    SQLNumResultCols.638756.1441906535.73.walk proc_call (?)
    SQLNumResultCols.638756.1441906535.73.walk call_cfunc_m1 (?)
    SQLNumResultCols.638756.1441906535.73.walk vm_call_cfunc_with_frame (?)
    SQLNumResultCols.638756.1441906535.73.walk vm_exec_core (?)
    SQLNumResultCols.638756.1441906535.73.walk vm_exec (?)
    SQLNumResultCols.638756.1441906535.73.walk invoke_block_from_c (?)
    SQLNumResultCols.638756.1441906535.73.walk vm_invoke_proc (?)
    SQLNumResultCols.638756.1441906535.73.walk proc_call (?)
    SQLNumResultCols.638756.1441906535.73.walk call_cfunc_m1 (?)
    SQLNumResultCols.638756.1441906535.73.walk vm_call_cfunc_with_frame (?)
    SQLNumResultCols.638756.1441906535.73.walk vm_exec_core (?)
    SQLNumResultCols.638756.1441906535.73.walk vm_exec (?)
    SQLNumResultCols.638756.1441906535.73.walk invoke_block_from_c (?)
    SQLNumResultCols.638756.1441906535.73.walk vm_invoke_proc (?)
    SQLNumResultCols.638756.1441906535.73.walk proc_call (?)
    SQLNumResultCols.638756.1441906535.73.walk call_cfunc_m1 (?)
    SQLNumResultCols.638756.1441906535.73.walk vm_call_cfunc_with_frame (?)
    SQLNumResultCols.638756.1441906535.73.walk vm_exec_core (?)
    SQLNumResultCols.638756.1441906535.73.walk vm_exec (?)
    SQLNumResultCols.638756.1441906535.73.walk invoke_block_from_c (?)
    SQLNumResultCols.638756.1441906535.73.walk vm_invoke_proc (?)
    SQLNumResultCols.638756.1441906535.73.walk proc_call (?)
    SQLNumResultCols.638756.1441906535.73.walk call_cfunc_m1 (?)
    SQLNumResultCols.638756.1441906535.73.walk vm_call_cfunc_with_frame (?)
    SQLNumResultCols.638756.1441906535.73.walk vm_exec_core (?)
    SQLNumResultCols.638756.1441906535.73.walk vm_exec (?)
    SQLNumResultCols.638756.1441906535.73.walk invoke_block_from_c (?)
    SQLNumResultCols.638756.1441906535.73.walk rb_yield (?)
    SQLNumResultCols.638756.1441906535.73.walk rb_ary_each (?)
    SQLNumResultCols.638756.1441906535.73.walk call_cfunc_0 (?)
    SQLNumResultCols.638756.1441906535.73.walk vm_call_cfunc_with_frame (?)
    SQLNumResultCols.638756.1441906535.73.walk vm_exec_core (?)
    SQLNumResultCols.638756.1441906535.73.walk vm_exec (?)
    SQLNumResultCols.638756.1441906535.73.walk invoke_block_from_c (?)
    SQLNumResultCols.638756.1441906535.73.walk vm_invoke_proc (?)
    SQLNumResultCols.638756.1441906535.73.walk proc_call (?)
    SQLNumResultCols.638756.1441906535.73.walk call_cfunc_m1 (?)
    SQLNumResultCols.638756.1441906535.73.walk vm_call_cfunc_with_frame (?)
    SQLNumResultCols.638756.1441906535.73.walk vm_exec_core (?)
    SQLNumResultCols.638756.1441906535.73.walk vm_exec (?)
    SQLNumResultCols.638756.1441906535.73.walk invoke_block_from_c (?)
    SQLNumResultCols.638756.1441906535.73.walk vm_invoke_proc (?)
    SQLNumResultCols.638756.1441906535.73.walk thread_start_func_2 (?)
    SQLNumResultCols.638756.1441906535.73.walk thread_start_func_1 (?)
    SQLNumResultCols.638756.1441906535.73.walk _pthread_body (?)
    SQLNumResultCols.638756.1441906535.73.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR)
    SQLNumResultCols.638756.1441906535.73.parm SQLHSTMT hstmt 0x3 (3)
    SQLNumResultCols.638756.1441906535.73.parm SQLSMALLINT* pccol 0x22888e54 (579374676)
    SQLNumResultCols.638756.1441906535.73.phex 22888e54 : 000000002293fb600000002000000000 >...."..`... ....<
    SQLNumResultCols.638756.1441906535.73.phex 22888e64 : 000000000000000000000000205a0978 >............ Z.x<
    SQLNumResultCols.638756.1441906535.73.phex 22888e74 : 204aca882293fb600000002000000000 > J.."..`... ....<
    SQLNumResultCols.638756.1441906535.73.phex 22888e84 : 000000005b5b00000000000800000ce8 >....[[..........<
    SQLNumResultCols.638756.1441906535.73.phex 22888e94 : 0000316022895ee00000002000000000 >..1`".^.... ....<
    SQLNumResultCols.638756.1441906535.73.tend ---error---
    
  79. Former user Account Deleted

    BTW -- we are not chasing our tails, we are on to something here (hounds are barking), so figuring out what ruby script was doing when the trace entry goes bad may hold the answer. That is to say that ruby gc decided to collect our hstmt, and, appears we still wanted to use it in Ruby script (ibm_db adapater perhaps).

  80. Aaron Bartell reporter

    but i am not sure i can synchronize/match trace log entries with rake trace. How would this be done?

    They'd be two separate logs and a visual/manual review would need to be done to correlate based on epoch timestamps and method-call names. I can actually setup the TracePoint to only log when Ruby calls C. That might be the best place to start. Stay tuned.

  81. Aaron Bartell reporter

    Observation: I don't believe I've ever experienced the column meta data error (ever) while in the rails console. I just tried to get the error to happen in rails console and was unable to, yet when I go to the browser to execute more or less the same database queries it errors frequently. I've been searching for things like "Rails view multithread issues" and am not finding others with same issue.

    Observation: One customer I am working with is also using the Ruby xmlservice gem via the DB2 approach and the calls to RPG programs go belly up frequently. When this happens it shuts down Thin and gives this message: Internal error in libdb400 calling SQL function SQLExecute. I am guessing this is because the xmlservice gem is using a stale DB2 connection handle.

    Thought: In the past you mentioned being on a Power5 machine. I have no idea how concurrency and parallelism has progressed as it relates to IBM i and multicore processors, but maybe that is why you can't recreate it? Note: I am on IBM i v7.2 Power7.

    These comments are simply to flavor our thoughts. I still plan on producing a new set of logs where we can see both the Ruby trace (mine) and paseclitrace(yours) side by side.

  82. Aaron Bartell reporter

    First round of libdb400 + Ruby trace is complete. libdb400_trace_692348.txt and libdb400_trace_692348_ruby.txt The Ruby trace format is class.method:lineno.epoch.ruby_thread_id. Note the ruby_thread_id is not the operating system thread id and instead the object_id of Thread.current.

    Below is what I added to the top of ibm_db_adapter.rb to produce the Ruby listing. Basically this will output to a file in /tmp every time a method call is made to ibm_db_adapter.rb.

    require 'active_record/connection_adapters/abstract_adapter'
    require 'arel/visitors/bind_visitor'
    
    module ActiveRecord
    
      trace = TracePoint.new(:call) do |tp|
        if tp.path.include? 'ibm_db_adapter.rb'
          File.open("/tmp/libdb400_trace_#{Process.pid}_ruby","a") do |file|
            file.write sprintf("%s.%s:%-2d.%s.%s\n", tp.defined_class, tp.method_id, tp.lineno, Time.now.to_i, Thread.current.object_id)
          end
        end
      end
      trace.enable
     . . .
    

    An Explanation

    The below sequence of active?, reconnect!, disconnect!, connect occurs hundreds of times in the log file. I believe the crazy number relates to asset (.js, .css, etc) requests which go through the full Rails request lifecycle, including readying the database for interaction, even though no interaction will take place. Something to fix another day.

    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.active?:1095.1442516438.303298440
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.reconnect!:1140.1442516438.303298440
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.disconnect!:1146.1442516438.303298440
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.connect:1103.1442516438.303298440
    

    Here are the API calls for a single refresh of the web page. Just good to see the call list.

    Arel::Visitors::IBM_DB.visit_Arel_Nodes_SelectStatement:3785.1442516437.303298440
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.quote_column_name:1863.1442516437.303298440
    ActiveRecord::ConnectionAdapters::HostedDataServer.check_reserved_words:3117.1442516437.303298440
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.add_limit_offset!:1715.1442516437.303298440
    ActiveRecord::ConnectionAdapters::IBM_DB2.query_offset_limit:2956.1442516437.303298440
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.to_sql:1059.1442516437.303298440
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.select:1282.1442516437.303298440
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.execute:1584.1442516437.303298440
    ActiveRecord::ConnectionAdapters::IBM_DataServer.execute:2287.1442516437.303298440
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.fetch_data:1245.1442516437.303298440
    ActiveRecord::ConnectionAdapters::IBM_DataServer.select:2217.1442516437.303298440
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.columns:2067.1442516437.303298440
    ActiveRecord::ConnectionAdapters::IBM_DB2_I5.columns:3326.1442516437.303298440
    ActiveRecord::ConnectionAdapters::IBM_DataServer.columns:2540.1442516437.303298440
    ActiveRecord::ConnectionAdapters::IBM_DB2.set_case:3054.1442516437.303298440
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.serverschema:891.1442516437.303298440
    ActiveRecord::ConnectionAdapters::IBM_DB2.set_case:3054.1442516437.303298440
    ActiveRecord::ConnectionAdapters::IBM_DB2.set_case:3054.1442516437.303298440
    ActiveRecord::ConnectionAdapters::IBM_DBColumn.simplified_type:593.1442516437.303298440
    ActiveRecord::ConnectionAdapters::IBM_DBColumn.type_cast:578.1442516437.303298440
    ActiveRecord::ConnectionAdapters::IBM_DBColumn.simplified_type:593.1442516437.303298440
    ActiveRecord::ConnectionAdapters::IBM_DBColumn.type_cast:578.1442516437.303298440
    ActiveRecord::ConnectionAdapters::IBM_DBColumn.simplified_type:593.1442516437.303298440
    ActiveRecord::ConnectionAdapters::IBM_DBColumn.type_cast:578.1442516437.303298440
    ActiveRecord::ConnectionAdapters::IBM_DBColumn.simplified_type:593.1442516438.303298440
    ActiveRecord::ConnectionAdapters::IBM_DBColumn.type_cast:578.1442516438.303298440
    ActiveRecord::ConnectionAdapters::IBM_DBColumn.simplified_type:593.1442516438.303298440
    ActiveRecord::ConnectionAdapters::IBM_DBColumn.type_cast:578.1442516438.303298440
    ActiveRecord::ConnectionAdapters::IBM_DBColumn.simplified_type:593.1442516438.303298440
    ActiveRecord::ConnectionAdapters::IBM_DBColumn.type_cast:578.1442516438.303298440
    ActiveRecord::ConnectionAdapters::IBM_DBColumn.simplified_type:593.1442516438.303298440
    ActiveRecord::ConnectionAdapters::IBM_DBColumn.type_cast:578.1442516438.303298440
    ActiveRecord::ConnectionAdapters::IBM_DBColumn.simplified_type:593.1442516438.303298440
    ActiveRecord::ConnectionAdapters::IBM_DBColumn.type_cast:578.1442516438.303298440
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.tables:1986.1442516438.303298440
    ActiveRecord::ConnectionAdapters::IBM_DB2.set_case:3054.1442516438.303298440
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.primary_key:2027.1442516438.303298440
    ActiveRecord::ConnectionAdapters::IBM_DB2.set_case:3054.1442516438.303298440
    ActiveRecord::ConnectionAdapters::IBM_DB2.set_case:3054.1442516438.303298440
    ActiveRecord::ConnectionAdapters::IBM_DBColumn.type_cast:578.1442516438.303298440
    ActiveRecord::ConnectionAdapters::IBM_DBColumn.type_cast:578.1442516438.303298440
    ActiveRecord::ConnectionAdapters::IBM_DBColumn.type_cast:578.1442516438.303298440
    ActiveRecord::ConnectionAdapters::IBM_DBColumn.type_cast:578.1442516438.303298440
    ActiveRecord::ConnectionAdapters::IBM_DBColumn.type_cast:578.1442516438.303298440
    ActiveRecord::ConnectionAdapters::IBM_DBColumn.type_cast:578.1442516438.303298440
    ActiveRecord::ConnectionAdapters::IBM_DBColumn.type_cast:578.1442516438.303298440
    ActiveRecord::ConnectionAdapters::IBM_DBColumn.type_cast:578.1442516438.303298440
    ActiveRecord::ConnectionAdapters::IBM_DBColumn.type_cast:578.1442516438.303298440
    ActiveRecord::ConnectionAdapters::IBM_DBColumn.type_cast:578.1442516438.303298440
    ActiveRecord::ConnectionAdapters::IBM_DBColumn.type_cast:578.1442516438.303298440
    ActiveRecord::ConnectionAdapters::IBM_DBColumn.type_cast:578.1442516438.303298440
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.active?:1095.1442516438.303298440
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.reconnect!:1140.1442516438.303298440
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.disconnect!:1146.1442516438.303298440
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.connect:1103.1442516438.303298440
    ActiveRecord::ConnectionAdapters::IBM_DataServer.set_schema:2303.1442516438.303298440
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.execute:1584.1442516438.303298440
    ActiveRecord::ConnectionAdapters::IBM_DataServer.execute:2287.1442516438.303298440
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.active?:1095.1442516438.304103370
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.reconnect!:1140.1442516438.304103370
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.disconnect!:1146.1442516438.304103370
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.connect:1103.1442516438.304103370
    ActiveRecord::ConnectionAdapters::IBM_DataServer.set_schema:2303.1442516439.304103370
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.execute:1584.1442516439.304103370
    ActiveRecord::ConnectionAdapters::IBM_DataServer.execute:2287.1442516439.304103370
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.active?:1095.1442516439.303298440
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.reconnect!:1140.1442516439.303298440
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.disconnect!:1146.1442516439.303298440
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.connect:1103.1442516439.303298440
    ActiveRecord::ConnectionAdapters::IBM_DataServer.set_schema:2303.1442516439.303298440
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.execute:1584.1442516439.303298440
    ActiveRecord::ConnectionAdapters::IBM_DataServer.execute:2287.1442516439.303298440
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.active?:1095.1442516439.304103370
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.reconnect!:1140.1442516439.304103370
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.disconnect!:1146.1442516439.304103370
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.connect:1103.1442516439.304103370
    ActiveRecord::ConnectionAdapters::IBM_DataServer.set_schema:2303.1442516439.304103370
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.execute:1584.1442516439.304103370
    ActiveRecord::ConnectionAdapters::IBM_DataServer.execute:2287.1442516439.304103370
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.active?:1095.1442516439.303298440
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.reconnect!:1140.1442516439.303298440
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.disconnect!:1146.1442516439.303298440
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.connect:1103.1442516439.303298440
    ActiveRecord::ConnectionAdapters::IBM_DataServer.set_schema:2303.1442516439.303298440
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.execute:1584.1442516439.303298440
    ActiveRecord::ConnectionAdapters::IBM_DataServer.execute:2287.1442516439.303298440
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.active?:1095.1442516439.304103370
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.reconnect!:1140.1442516439.304103370
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.disconnect!:1146.1442516439.304103370
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.connect:1103.1442516439.304103370
    ActiveRecord::ConnectionAdapters::IBM_DataServer.set_schema:2303.1442516439.304103370
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.execute:1584.1442516439.304103370
    ActiveRecord::ConnectionAdapters::IBM_DataServer.execute:2287.1442516439.304103370
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.active?:1095.1442516439.303298440
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.reconnect!:1140.1442516439.303298440
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.disconnect!:1146.1442516439.303298440
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.connect:1103.1442516439.303298440
    ActiveRecord::ConnectionAdapters::IBM_DataServer.set_schema:2303.1442516439.303298440
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.execute:1584.1442516439.303298440
    ActiveRecord::ConnectionAdapters::IBM_DataServer.execute:2287.1442516439.303298440
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.active?:1095.1442516439.304103370
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.reconnect!:1140.1442516439.304103370
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.disconnect!:1146.1442516439.304103370
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.connect:1103.1442516439.304103370
    ActiveRecord::ConnectionAdapters::IBM_DataServer.set_schema:2303.1442516439.304103370
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.execute:1584.1442516439.304103370
    ActiveRecord::ConnectionAdapters::IBM_DataServer.execute:2287.1442516439.304103370
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.active?:1095.1442516440.303298440
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.reconnect!:1140.1442516440.303298440
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.disconnect!:1146.1442516440.303298440
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.connect:1103.1442516440.303298440
    ActiveRecord::ConnectionAdapters::IBM_DataServer.set_schema:2303.1442516440.303298440
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.execute:1584.1442516440.303298440
    ActiveRecord::ConnectionAdapters::IBM_DataServer.execute:2287.1442516440.303298440
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.to_sql:1059.1442516440.303298440
    

    I am continuing to look through the log to find other patterns.

  83. Former user Account Deleted

    Aaron, I tried my fancy new power 8 box, and, lateset IBM i release. Everything works fine (no missing records), aka, i can not reproduce your multiple thread error.

    Oh boy, oh boy, I want your to try my version of ibm_db2 gem ... my test version ibm_db

    Yes, yes, please may i be wrong about my version working ... BUT ... we really have to try this experiment. If my version works we better take this conversation off-line.

    Aaron only
    
        {ibm_db test} - (2.5.14 my version)
    
        cd /PowerRuby/prV2R1/lib/ruby/gems/2.1.0/gems
        tar -xf ibm_db-2.5.14.zip
    
            (may i be wrong … yikes) 
    
  84. Aaron Bartell reporter

    I am still getting the error. Here's what I did...

    First I created a separate location to place the Gem:

    $ mkdir -p /ruby/gemsets/ibm_db-tony/gems
    $ mkdir /ruby/gemsets/ibm_db-tony/specifications
    

    FTP'd the now unzipped files to /ruby/gemsets/ibm_db-tony/gems. Added a line at the top of ibm_db_adapter.rb so I can be sure I am picking up your version.

    $ echo "puts 'Tony version'" | cat - /ruby/gemsets/gems/ibm_db-tony/gems/ibm_db-2.5.14-powerpc-aix-6/lib/active_record/connection_adapters/ibm_db_adapter.rb > /tmp/out && mv /tmp/out /ruby/gemsets/ibm_db-tony/gems/ibm_db-2.5.14-powerpc-aix-6/lib/active_record/connection_adapters/ibm_db_adapter.rb
    

    Need specifications file so Gem can be resolved. (Did you not have to do this?)

    cp /ruby/gemsets/ibmdb_fetchbug-development/specifications/ibm_db-2.5.14-powerpc-aix-6.gemspec /ruby/gemsets/ibm_db-tony/specifications
    

    Setup environment vars for precedence:

    $ export GEM_HOME=/ruby/gemsets/ibm_db-tony
    $ export GEM_PATH=/ruby/gemsets/ibm_db-tony:/PowerRuby/prV2R1/lib/ruby/gems/2.1.0
    

    Output during startup to confirm I am picking up your version:

    $ rails s -p50000
    /PowerRuby/prV2R1/lib/ruby/gems/2.1.0/gems/railties-4.1.8/lib/rails/app_rails_loader.rb:37: warning: Insecure world writable dir /QOpenSys in PATH, mode 042777
    /PowerRuby/prV2R1/lib/ruby/gems/2.1.0/gems/bundler-1.7.6/lib/bundler/runtime.rb:222: warning: Insecure world writable dir /QOpenSys in PATH, mode 042777
    Tony version
    => Booting Puma
    => Rails 4.1.8 application starting in development on http://0.0.0.0:50000
    => Run `rails server -h` for more startup options
    => Notice: server is listening on all interfaces (0.0.0.0). Consider using 127.0.0.1 (--binding option)
    => Ctrl-C to shutdown server
    Puma 2.11.1 starting...
    * Min threads: 0, max threads: 16
    * Environment: development
    * Listening on tcp://0.0.0.0:50000
    
    
    Started GET "/users" for 69.24.176.225 at 2015-09-21 21:59:22 +0000
       (8.2ms)  SET SCHEMA ab1_d
       (7.6ms)  SET SCHEMA ab1_d
      ActiveRecord::SchemaMigration Load (15.4ms)  SELECT schema_migrations.* FROM schema_migrations
    Processing by UsersController#index as HTML
      User Load (3.2ms)  SELECT users.* FROM users
      Rendered users/index.html.erb within layouts/application (197.0ms)
    Completed 200 OK in 434ms (Views: 385.1ms | ActiveRecord: 3.2ms)
    

    After 15 to 20 refreshes I get the follow error:

    Started GET "/users" for 69.24.176.225 at 2015-09-21 21:59:55 +0000
       (8.3ms)  SET SCHEMA ab1_d
    Processing by UsersController#index as HTML
      User Load (16.3ms)  SELECT users.* FROM users
      Rendered users/index.html.erb within layouts/application (35.2ms)
    Completed 500 Internal Server Error in 44ms
    
    ActionView::Template::Error (uncaught throw :"Column information cannot be retrieved: <error message could not be ret rieved>"):
        13:   </thead>
        14:
        15:   <tbody>
        16:     <% @users.each do |user| %>
        17:       <tr>
        18:         <td><%= user.name %></td>
        19:         <td><%= user.age %></td>
      app/views/users/index.html.erb:16:in `_app_views_users_index_html_erb___533735991_289853340'
    
    
      Rendered /PowerRuby/prV2R1/lib/ruby/gems/2.1.0/gems/actionpack-4.1.8/lib/action_dispatch/middleware/templates/rescues/_trace.html.erb (3.3ms)
      Rendered /PowerRuby/prV2R1/lib/ruby/gems/2.1.0/gems/actionpack-4.1.8/lib/action_dispatch/middleware/templates/rescues/_request_and_response.html.erb (21.8ms)
      Rendered /PowerRuby/prV2R1/lib/ruby/gems/2.1.0/gems/actionpack-4.1.8/lib/action_dispatch/middleware/templates/rescues/template_error.html.erb within rescues/layout (88.7ms)
    

    Maybe tar up your entire /PowerRuby folder so I can ensure I have everything the exact same as you?

  85. Former user Account Deleted

    Ok i have download ... big ... you may need to use FTP to yips ...

    Aaron only
    
        {powerruby} - (my version)
    
  86. Aaron Bartell reporter

    I've loaded the "Aaron only" version of PowerRuby into a chroot environment and am able to reproduce the issue.

    I wish I could say it is unique to my particular machine but I've experienced the error on every machine I've worked on (customer's servers, AITP RubyOnRails contest servers, KrengelTech servers, QUSER.org training server, WMCPA.org training server, etc).

    Possible options for next steps that I can think of:

    • Tell me what traces/scenarios to try next.
    • Web meeting where you watch me recreate the error and I watch you to see where our process might be different.
    • I give you access to a chroot environment on my internet-facing server (no VPN required) that you can SSH into and recreate the error. I would need your id_rsa.pub ssh key as I've turned off ssh password authentication.
  87. Former user Account Deleted

    well, can we see a trace of the failing 'test', using Aaron Only PowerRuby?

    aka, we already know what is wrong, garbage collector appears to be collecting a "in use" statement handle (naughty garbage collector).

  88. Former user Account Deleted

    Well, same sequence ...

    1) la dee da red riding hood ... ibm_db_exec -> SQLExecDirect 2) big bad wolf ... gc_finalize_deferred->SQLFreeHandle 3) scream ... ibm_db_result_cols -> SQLNumResultCols

    So, it would appear that ruby Garbage Collector will not stop eating grandma #3 staetment handle ... naughty, naughty, naughty ... Mr. GC!

    So, we have it coded wrong in c code, or, we need to hide our grandma statement handles/resources in closet, away resources from big bad wolf Mr GC.

    SQLExecDirect.726139.1442947138.1.tbeg +++success+++
    SQLExecDirect.726139.1442947138.1.walk dump_SQLExecDirect (0 3 23234bd0 1a)
    SQLExecDirect.726139.1442947138.1.walk SQLExecDirect (3 23234bd0 1a)
    SQLExecDirect.726139.1442947138.1.walk _ruby_ibm_db_SQLExecDirect_helper (?)
    SQLExecDirect.726139.1442947138.1.walk ibm_db_exec (?)
    
    SQLFreeHandle.726139.1442947138.1.tbeg +++success+++
    SQLFreeHandle.726139.1442947138.1.walk dump_SQLFreeHandle (0 30003 3)
    SQLFreeHandle.726139.1442947138.1.walk SQLFreeHandle (30003 3)
    SQLFreeHandle.726139.1442947138.1.walk _ruby_ibm_db_free_stmt_struct (?)
    SQLFreeHandle.726139.1442947138.1.walk finalize_list (?)
    SQLFreeHandle.726139.1442947138.1.walk gc_finalize_deferred (?)
    SQLFreeHandle.726139.1442947138.1.walk rb_postponed_job_flush (?)
    SQLFreeHandle.726139.1442947138.1.walk rb_threadptr_execute_interrupts.part.37 (?)
    SQLFreeHandle.726139.1442947138.1.walk vm_exec_core (?)
    SQLFreeHandle.726139.1442947138.1.walk vm_exec (?)
    
    SQLNumResultCols.726139.1442947138.1.tbeg ---error---
    SQLNumResultCols.726139.1442947138.1.walk dump_SQLNumResultCols (fffffffe 3 212b25b4)
    SQLNumResultCols.726139.1442947138.1.walk SQLNumResultCols (3 212b25b4)
    SQLNumResultCols.726139.1442947138.1.walk _ruby_ibm_db_SQLNumResultCols_helper (?)
    SQLNumResultCols.726139.1442947138.1.walk _ruby_ibm_db_get_result_set_info (?)
    SQLNumResultCols.726139.1442947138.1.walk ibm_db_result_cols (?)
    
  89. Former user Account Deleted

    The other possibility was that the ruby script code (ibm db adapter), has scope of the statement incorrectly designed. That is, #3 statement goes out of scope between ibm_db_exec and ibm_db_result_cols ... but ... you are already working on a converged trace to help us understand what the bloody ruby code was doing at the time of #3 statement death-by-garbage-collector.

  90. Former user Account Deleted

    Are you understanding all of this feedback?? And, do you believe what i am saying???

  91. Aaron Bartell reporter

    So, we have it coded wrong in c code,

    And by that are you talking about the Ruby c code or ibm_db.c? The latter we can affect within this code base. The former we'd need to engage the PowerRuby team.

    Also, should we convey our findings to the LUW ibm_db group (this issue)? I am wondering if they'd know right where to fix this or maybe they already have.

  92. Aaron Bartell reporter

    Are you understanding all of this feedback?? And, do you believe what i am saying???

    The latest results had one thread (from what I could see) so that causes me to lean towards Mr. GC being the issue. So yes, I agree with the current direction.

    but ... you are already working on a converged trace to help us understand what the bloody ruby code was doing at the time of #3 statement death-by-garbage-collector.

    I did produce two traces in this post (one paseclitrace and the other Ruby) from late last week but you didn't comment on it so I don't know if it was useful. Maybe TL;DR? Do you want me to run it again with the PowerRuby version you gave me?

  93. Former user Account Deleted

    Mmm ... sorry, doing many things at same time ... i have not yet figured out how to merge two trace files, are you working on a tool to 'merge' into one file (i thought your were)???

  94. Aaron Bartell reporter

    i have not yet figured out how to merge two trace files, are you working on a tool to 'merge' into one file (i thought your were)???

    I can, yes, but I originally asked for clarity to make sure I was going to produce what you envisioned/needed. Your above comment gives me direction (you want the two files merged and not just queried/searched).

    Below is an example I manually copy/pasted where entries from paseclitrace and Ruby trace are sorted by timestamp. Is that basically what you are looking for?

    SQLOverrideCCSID400.692348.1442516426.1.tbeg +++success+++
    SQLOverrideCCSID400.692348.1442516426.1.walk dump_SQLOverrideCCSID400 (0 4b8)
    SQLOverrideCCSID400.692348.1442516426.1.walk SQLOverrideCCSID400 (4b8)
    SQLOverrideCCSID400.692348.1442516426.1.walk _ruby_ibm_db_SQLOverrideCCSID400_helper (?)
    SQLOverrideCCSID400.692348.1442516426.1.walk ruby_init_ibm_db (?)
    SQLOverrideCCSID400.692348.1442516426.1.walk Init_ibm_db (?)
    SQLOverrideCCSID400.692348.1442516426.1.walk dln_load (?)
    SQLOverrideCCSID400.692348.1442516426.1.walk load_ext (?)
    SQLOverrideCCSID400.692348.1442516426.1.walk rb_vm_call_cfunc (?)
    SQLOverrideCCSID400.692348.1442516426.1.walk rb_require_safe (?)
    #<Class:ActiveRecord::Base>.ibm_db_connection:290.1442516436.303298440
    ActiveRecord::ConnectionAdapters::TableDefinition.initialize:720.1442516427.303298440
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.initialize:899.1442516427.303298440
    ActiveRecord::ConnectionAdapters::IBM_DB2_I5.initialize:3240.1442516427.303298440
    ActiveRecord::ConnectionAdapters::IBM_DB2.initialize:2630.1442516427.303298440
    ActiveRecord::ConnectionAdapters::IBM_DataServer.initialize:2178.1442516427.303298440
    ActiveRecord::ConnectionAdapters::IBM_DataServer.set_schema:2303.1442516427.303298440
    ActiveRecord::ConnectionAdapters::IBM_DBAdapter.execute:1584.1442516427.303298440
    ActiveRecord::ConnectionAdapters::IBM_DataServer.execute:2287.1442516427.303298440
    
  95. Former user Account Deleted

    ok, but what was happening around the actual error ...

    1) where was ruby script here ...
    SQLExecDirect.726139.1442947138.1.tbeg +++success+++
    2) where was ruby script here ... (this one you may not find)
    SQLFreeHandle.726139.1442947138.1.tbeg +++success+++
    3) where was ruby script here ...
    SQLNumResultCols.726139.1442947138.1.tbeg ---error---
    
  96. Former user Account Deleted

    As far a c-code, i doubt LUW will have any idea what you are talking about, although, i thought you said they were also experiencing issue on Linux. Anyway, We/You/Me have CLI trace with walk back to actually see GC interrupt the ruby script to process the garbage. LUW has nothing even close to this level of details (just so you understand how good this trace is actually).

    The steps ...

    ... after we eliminate ruby ibm_db adapter scope, aka, find merged two trace to identify locations when SQLNumResultCols occurred

    ... then we decide if it looks like c code error (it does look like bad c code not so far).

    ... last, we fix either the ruby code or the c code (perhaps need to hack away from ruby GC)

  97. Aaron Bartell reporter

    Merge program is complete and I have a first round for us to look at.

    ##Files - libdb400_trace_727067_merged_sorted.txt <--- What we are currently interested in - libdb400_trace_727067.txt - libdb400_trace_727067_ruby.txt

    Note libdb400_trace_727067_merged_sorted.txt has junk lines in the beginning because some of the libdb400 trace lines don't include the API name and cut the epoch in the middle (see below for example).

    SQLNumResultCols.727067.1442970011.1.tend +++success+++
    2970011.1.walk vm_call0_body.constprop.63 (?)     <-----this one is missing API and portion of epoch
    SQLDescribeCol.727067.1442970011.1.walk rb_call0 (?)
    

    ibm_db_adapter.rb insertion

    Below is how I am collecting all method calls occurring in ibm_db_adapter.rb. Note: I could go beyond :call event notifications if we need it (based on Ruby TracePoint docs).

    require 'active_record/connection_adapters/abstract_adapter'
    require 'arel/visitors/bind_visitor'
    
    module ActiveRecord
      trace = TracePoint.new(:call) do |tp|
        if tp.path.include? 'ibm_db_adapter.rb'
          File.open("/tmp/libdb400_trace_#{Process.pid}_ruby","a") do |file|
            file.write sprintf("%s.%s:%-2d.%s.%s\n", tp.defined_class, tp.method_id, tp.lineno, Time.now.to_i, Thread.current.object_id)
          end
        end
      end
      trace.enable
    

    ##Merge Program This is the merge program. I put the epoch and iterator at the beginning of each line so the subsequent sort would succeed.

    # $ ruby trace_merge.rb /tmp/libdb400_trace_727067 /tmp/libdb400_trace_727067_ruby /tmp/libdb400_trace_727067_merged.txt
    
    File.open(ARGV[2], "w") do |merged_file|
      [ARGV[0], ARGV[1]].each do |in_file| 
        i = 1
        IO.foreach(in_file) do |line|
    
          key = line.split '.'
          str = "file_" + i.to_s.rjust(7, "0")
          merged_file.puts(key[2] + "-#{i.to_s.rjust(7, "0")}---" + line) rescue merged_file.puts('ZZ unable to split line---' + line)
          i += 1
        end
      end
    end
    

    ##Sort

    $ sort /tmp/libdb400_trace_727067_merged.txt > /tmp/libdb400_trace_727067_merged_sorted.txt
    
  98. Former user Account Deleted

    Mmm ... seems like a lot of work ... maybe i could just provide you a new call in libdb400.a like SQLAddMyTraceData(string), thereby, all the time/thread/key data would be "auto magically" taken care. We just a 'internal dynamic' function _db2_add_trace(string) to ibm_db2.c, and, if libdb400.a exported the signature, you can simply call it. What do you think???

  99. Aaron Bartell reporter

    seems like a lot of work ...

    I digressed into details for historical purposes. In the end you only need to look at this file to see when Ruby/SQL CLI events occur. With that said...

    maybe i could just provide you a new call in libdb400.a like SQLAddMyTraceData(string), thereby, all the time/thread/key data would be "auto magically" taken care.

    Yes, that would be perfect.

  100. Former user Account Deleted

    Nuts, i can't make heads or tails out of the merged list, i think you need to use something other than "walk" in your key, aka, c code says walk, ruby code says "run" or something like that. Anyway per previous, this whole idea trace in ruby may be better via a db2_add_trace(string) function, and, let the libdb400.a trace module deal with "merge".

    What do you think?

  101. Aaron Bartell reporter

    Anyway per previous, this whole idea trace in ruby may be better via a db2_add_trace(string) function, and, let the libdb400.a trace module deal with "merge". What do you think?

    Yes, that would be a good direction.

  102. Former user Account Deleted

    BTW -- just so i do not forget, we may have to make use of RB_GC_GUARD in the ibm_db c code (hide from ruby GC), some comments about Ruby GC in relation to compiler optimizations. ruby gc

  103. Aaron Bartell reporter

    Am I correct to understand from that article we will be using RB_GC_GUARD on SQL CLI handles?

    Unsure if related but Ruby has a concept of "copy on write" for parameters. This guy digresses through it nicely.

  104. Former user Account Deleted

    Yes, "guard" SQL handles. However, our mixed trace has not yet eliminated a simple 'scope of statement' error in ruby script side (yet). But, mmm, leaning, ahh, leaning, toward using the guard, because eveidence both on IBM i and other LUW dealing with Ruby GC..

    .... but, but, but, relatively sophisticated article points out, we should NEVER have to 'guard' against a design 'error'. Aka, depending on which PHD talking, Ruby guys messed up over engineering for performance sake (common problem for garbage collecting in any language).

  105. Former user Account Deleted

    BTW -- interesting,brings to mind a Clint Eastwood movie ...

    Good -- advertising greatness of Ruby CG design good

    Bad -- proclaiming terrible Ruby GC design bad

    Ugly -- well, we seem to clearly be having problems with Ruby GC jumping in and destroying our 'in use' handles. Not only IBM i, but on LUW ibm_db in other messages ...

    We all see the world as we wish i guess ... but ... we still need the mixed trace data.

  106. Aaron Bartell reporter

    #"Don't die, I'll get you water. Stay there. Don't move, I'll get you water. Don't die until later." - Tuco

    Looking forward to the mixed trace data API. Will implement it asap.

  107. Former user Account Deleted

    Sorry, i was pointing he finger to me on the trace ... i need to add a new feature db2_add_trace(string) function, may not give us all we need, but could help eliminate easier ruby script issues as they come up.

    Btw -- again, i am most interested in giving YOU the ability to work issues with confidence. In the end, if this is a ruby GC design, we probably will simply 'guard' our way out of the maze ... and ... while the trace was useful to detect the issue, it still left subjective understanding to the authors of the c code (you and me). Therein, we would need to work together on a crazy animal like this as it sits on the edge of PHDs arguing above all listening.

  108. Aaron Bartell reporter

    i am most interested in giving YOU the ability to work issues with confidence.

    I am getting more confident in how to debug and what the parts of the traces are conveying, but it's knowing gc_finalize_deferred are red flags is where I lack. I suppose that will have to come with time. I will eventually be writing articles about this lower-level debugging stuff but I needed to get all the "intro to xxxx" stuff done first so people are actually using this open source/PASE.

  109. Former user Account Deleted

    Off topic (not part of issue), your question about "copy on write" ...

    "The speed" of forked process Linux/AIX/PASE are build on "copy on write" principle. That is to say, when a parent process/job forks a child process it still has exact memory image of the parent, BUT, any changes (writes) child makes to any memory results in a "copy on write" "page". You can think of parent process freezing it's memory image at fork time (except to itself -- parent only write), wherein child only allowed to read, and, if child changes he gets his own 'alias' copy of the memory to replace the frozen parent memory. Needless to say, this is a VERY efficient model, in that, a child job that does not 'exec' (run new program), will likely leave a high percentage of the memory untouched.

    Similar topic, using same "copy on write" idea, kernel program loaders of Linux/AIX/PASE load shared stuff (libthing.a and thing.so) into kernel parent memory image for text/code and data. where, shared is defined by file system other *RX bits, on shared thing.so, aka, none shared loads from scratch into process private memory. Anyway, assuming shared (90% case), new process started form anywhere on the machine inherits the pre-resolved image of the library tree (dependencies), and, like our fork mechanics, changes to data parts of the shared library memory (variables inside the thing.so), form "copy on write" chunks in the new process.

    The article ...

    Possibly this server is running Apache with something like Passenger that forks a separate Ruby process to handle each HTTP request.

    well, mmm, cough, we all know Ruby/Rails MOST applications are pre-start daemon and thread oriented, therefore NEVER spawn/fork new processes to handle work ... so ... gee ... "copy on write" for process ... gee ... well even FAstCGI spawns then keeps active .. so .. gee ... mmm ... what is the nice way to say "who cares"??

  110. Former user Account Deleted

    Ok, i have a merged trace ...

    module ActiveRecord
      #############################
      # trace -- (Aaron)
      #############################
      trace = TracePoint.new(:call) do |tp|
        if tp.path.include? 'ibm_db_adapter.rb'
          IBM_DB.trace(sprintf("%s %s %-2d", tp.defined_class, tp.method_id, tp.lineno))
        end
      end
      trace.enable
    

    ... but ... creates a lot of data ...

    SQLFreeHandle.40907.1443477662.3.tend +++success+++
    script.40907.1443477662.3.run ActiveRecord::ConnectionAdapters::IBM_DBColumn type_cast 578
    script.40907.1443477662.3.run ActiveRecord::ConnectionAdapters::IBM_DBColumn type_cast 578
    script.40907.1443477662.3.run hey adc i am in welcome controller
    script.40907.1443477662.3.run ActiveRecord::ConnectionAdapters::IBM_DBAdapter quote_column_name 1821
    script.40907.1443477662.3.run ActiveRecord::ConnectionAdapters::HostedDataServer check_reserved_words 3075
    script.40907.1443477662.3.run ActiveRecord::ConnectionAdapters::IBM_DBAdapter tables 1944
    script.40907.1443477662.3.run ActiveRecord::ConnectionAdapters::IBM_DB2 set_case 3012
    SQLAllocHandle.40907.1443477662.3.tbeg +++success+++
    SQLAllocHandle.40907.1443477662.3.walk dump_SQLAllocHandle (0 30003 2 2301fa14)
    SQLAllocHandle.40907.1443477662.3.walk SQLAllocHandle (30003 2 2301fa14)
    

    So, i am thinking options for script paseclitrace.ini ... or ... maybe something in ruby trace (see trace Aaron in ibm_db_adapter.rb above) ...

    have any ideas???

  111. Aaron Bartell reporter

    So, i am thinking options for script paseclitrace.ini ... or ... maybe something in ruby trace (see trace Aaron in ibm_db_adapter.rb above) ...

    How about a generic lang_trace_type option:

    ; lang_trace_type
    ;   0 - trace all
    ;   1 - trace warnings
    ;   2 - trace errors only
    lang_trace_type=0
    

    Then we can use this for Node.js, Python, Scala, etc. Each language/programmer will be responsible for implementing their concept of what levels 0,1,2 mean (or they could ignore them completely).

    Could you put the new trace on YiPs?

  112. Former user Account Deleted

    No, unfortunately is chicken and egg for the script. That is to say ruby 'script code' does not know there will be an error until after call to CLI driver libdb400.a (c code), and, has already logged "i am here in my script".

    So i am beginning to think we will have to offer some sort of secondary calls ...

    # 1) default trace everything, but exclude where these strings appear
    IBM_DB.trace_exclude('type_cast','simplified_type', ...)
    
    -- or --
    
    # 2) default trace nothing, but include only where these strings appear
    IBM_DB.trace_include('execute','fetch_data', ...)
    
  113. Former user Account Deleted

    However, i like additional control idea enable off/on script tracing ...

    ; script_trace_type
    ;   0 - script off
    ;   1 - script on
    script_trace_type=1
    
  114. Aaron Bartell reporter

    Could trace_exclude and trace_include accept a regex so it is configurable in a single parameter with better matching capabilities?

    Thumbs up on script_trace_type and corresponding options.

  115. Former user Account Deleted

    No regex (i knew you would ask). Trace version of libdb400.a is a simple c program, from a simple man (me), no dependencies on anything esoteric like "regex", aka, i will not sign-up to build and/or make a dependency on a library IBM does not ship. No, this will be a simple strcmp of the array elements appear in the list (yes/no).

  116. Aaron Bartell reporter

    i will not sign-up to build and/or make a dependency on a library IBM does not ship.

    Does IBM intend to ship this trace utility with IBM i?

  117. Former user Account Deleted

    No. In fact, probably another Open Source project for us.

    However, perhaps leads to IBM PTF in future, IF/when people start to understand what this new feature offers.

    BTW -- I am a true believer in open source model, try it out, if good, keep it active in the community. Yes, our community is small (me/you), but every tree starts from a seed.

  118. Former user Account Deleted

    Ok, I have new ibm_db gem source that included RUBY_GC_GUARD (*). I tested and works fine on my machine, but, well, i never had the problem. So i guess test falls to you and your machine. ibm_db gem source

    I have a new libdb400.a 1.0.6 trace enables merged log files using IBM_DB.trace("msg"), etc. libdb400.a 1.0.6

    (*) Note: Assuming all goes well with your test ... I can NOT legally post a pre-compiled ibm_db gem as 'IBM' (i don't believe). Can you volunteer for 'build role' for others that need ibm_db gem update??? ... other ideas???

  119. Aaron Bartell reporter

    What approach are you using to compile this gem? I am reviewing zzall_ibm_i.sh and see that the gem compile line is commented out. I believe gem compile is meant to use the gem-compiler Gem. Just want to make sure I am approaching it the same way.

    Can you volunteer for 'build role' for others that need ibm_db gem update???

    Yes, I can play the build role.

  120. Former user Account Deleted

    i use zzall_ibm_i.sh "as is" with xlc compiler and everything works for me, perhaps gem compile is implicit step apparently during gem install.

  121. Former user Account Deleted

    Oh boy, I am using the gcc compiler with zzall_ibm_i.sh (not xlc). I am soooo sorry if i made you chase a xlc compiler download. Here is the compiler i am using.

    bash-4.3$ gcc --version
    gcc (GCC) 4.8.3
    Copyright (C) 2013 Free Software Foundation, Inc.
    This is free software; see the source for copying conditions.  There is NO
    warranty; not even for MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.
    
  122. Aaron Bartell reporter

    Ok, silly question, but what do I need to install to get include file sqlcli1.h?

    % gem install ./ibm_db-2.5.15.pre.beta.gem --local --force --ignore-dependencies --no-rdoc
    Building native extensions.  This could take a while...
    /PowerRuby/prV2R1/lib/ruby/site_ruby/2.1.0/rubygems/ext/builder.rb:73: warning: Insecure world writable dir /QOpenSys in PATH, mode 042777
    ERROR:  Error installing ./ibm_db-2.5.15.pre.beta.gem:
            ERROR: Failed to build gem native extension.
    
        /PowerRuby/prV2R1/bin/ruby -r ./siteconf20151002-751915-1r2ci0q.rb extconf.rb
    extconf.rb:13: warning: Insecure world writable dir /QOpenSys in PATH, mode 042777
    Detected 32-bit Ruby
    
    compile type 3) Ruby >= 1.9 IBM i PASE_RELEASE_VERSION
    extconf.rb:134: warning: already initialized constant IBM_DB_HOME
    extconf.rb:28: warning: previous definition of IBM_DB_HOME was here
    creating gil_release_version
    creating unicode_support_version
    checking for gil_release_version... yes
    checking for unicode_support_version... yes
    creating Makefile
    
    make "DESTDIR=" clean
    
    make "DESTDIR="
    compiling ibm_db.c
    In file included from ruby_ibm_db_cli.h:20:0,
                     from ruby_ibm_db.h:17,
                     from ibm_db.c:32:
    ruby_sql_com.h:80:61: fatal error: sqlcli1.h: No such file or directory
     #include <sqlcli1.h> /* include top for overrided to work */
    
  123. Former user Account Deleted

    In gem, I included zzcopyincludes_ibm_i.sh shell script to copy CLI includes from ILE to PASE.

    $ cat zzcopyincludes_ibm_i.sh 
    #!/QOpenSys/usr/bin/ksh
    ls /QIBM/include/sql* > ./list2
    for i in $(< ./list2)
    do
      echo "PREPARATION COPY"
      system -v "CPY OBJ('$i') TODIR('/usr/include/') TOCCSID(*STDASCII) DTAFMT(*TEXT) REPLACE(*YES)"                                      
    done
    rm list2
    

    However, LUW uses sqlcli1.h (everywhere), so please add that include to PASE as follows.

    bash-4.3$ cat /usr/include/sqlcli1.h 
    #include "sql.h"
    #include "sqlca.h"
    #include "sqlcli.h"
    
  124. Aaron Bartell reporter

    Good news: I am now successfully compiling the gem.

    Bad news: I am still getting the error. Here is the new combined log using the latest gem and tracing.

  125. Former user Account Deleted

    Disappointing, same sequence of bad Ruby GC behaviour. Well, we will have to take stronger measures to keep our active statements away from the snarling teeth of the Ruby GC ... bad gc dog, bad gc dog!!

    ===== RUBY CG double deletes nearly all the time ====
    SQLFreeHandle.752347.1443822136.13.walk gc_finalize_deferred (?)
    SQLFreeHandle.752347.1443822136.13.walk gc_finalize_deferred (?)
    SQLFreeHandle.752347.1443822136.13.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR)
    
    
    ==== same sequence Ruby CG delete active statement ========
    SQLFreeHandle.752347.1443822262.105.tbeg +++success+++
    SQLFreeHandle.752347.1443822262.105.walk dump_SQLFreeHandle (0 30003 3)
    SQLFreeHandle.752347.1443822262.105.walk SQLFreeHandle (30003 3)
    SQLFreeHandle.752347.1443822262.105.walk _ruby_ibm_db_free_stmt_struct (?)
    SQLFreeHandle.752347.1443822262.105.walk finalize_list (?)
    SQLFreeHandle.752347.1443822262.105.walk gc_finalize_deferred (?)
    :
    SQLFreeHandle.752347.1443822262.105.retn SQLRETURN sqlrc 0x0 (0) SQL_SUCCESS
    SQLFreeHandle.752347.1443822262.105.parm SQLSMALLINT htype 0x3 (3)
    SQLFreeHandle.752347.1443822262.105.parm SQLINTEGER hndl 0x3 (3)
    SQLFreeHandle.752347.1443822262.105.tend +++success+++
    SQLNumResultCols.752347.1443822262.105.tbeg ---error---
    SQLNumResultCols.752347.1443822262.105.walk dump_SQLNumResultCols (fffffffe 3 21ac6934)
    SQLNumResultCols.752347.1443822262.105.walk SQLNumResultCols (3 21ac6934)
    SQLNumResultCols.752347.1443822262.105.walk _ruby_ibm_db_SQLNumResultCols_helper (?)
    SQLNumResultCols.752347.1443822262.105.walk _ruby_ibm_db_get_result_set_info (?)
    SQLNumResultCols.752347.1443822262.105.walk ibm_db_result_cols (?)
    :
    SQLNumResultCols.752347.1443822262.105.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR)
    SQLNumResultCols.752347.1443822262.105.parm SQLHSTMT hstmt 0x3 (3)
    SQLNumResultCols.752347.1443822262.105.parm SQLSMALLINT* pccol 0x21ac6934 (564947252)
    SQLNumResultCols.752347.1443822262.105.phex 21ac6934 : 0000000021ac6ac00000002000000000 >....!.j.... ....<
    SQLNumResultCols.752347.1443822262.105.phex 21ac6944 : 000000000000000000000000205a0978 >............ Z.x<
    SQLNumResultCols.752347.1443822262.105.phex 21ac6954 : 0000000021ac6ac00000002000000000 >....!.j.... ....<
    SQLNumResultCols.752347.1443822262.105.phex 21ac6964 : 000000005b5b00000000001a64622f6d >....[[......db/m<
    SQLNumResultCols.752347.1443822262.105.phex 21ac6974 : 6967726174652f2a2a2f5b302d395d2a >igrate/**/[0-9]*<
    SQLNumResultCols.752347.1443822262.105.tend ---error---
    
  126. Former user Account Deleted

    Aaron, Ok, i have temporarily removed Ruby GC from collecting statement handles (i think). Please give this new version a try and see if the issue disappears.

    --- this is where ruby GC is notified ok to mark, free our statement handles ---
    
                _ruby_ibm_db_mark_stmt_struct, _ruby_ibm_db_free_stmt_struct,
                    stmt_res);
                RB_GC_GUARD(return_value);
    
    --- this is where ruby CG actually frees our handles, and, i commented out the delete (for now/test) ---
    
    /*  static _ruby_ibm_db_free_stmt_struct */
    static void _ruby_ibm_db_free_stmt_struct(stmt_handle *handle)
    {
    /* ADC -- fix this after test.
      if ( handle != NULL ) {
        _ruby_ibm_db_free_stmt_handle_and_resources( handle );
        ruby_xfree( handle );
        handle = NULL;
      }
    */
    }
    
  127. Former user Account Deleted

    Sorry, my cut paste did not grab the whole statement for your to see the mark, free wrap ...

                return_value = Data_Wrap_Struct(le_stmt_struct,
                _ruby_ibm_db_mark_stmt_struct, _ruby_ibm_db_free_stmt_struct,
                    stmt_res);
                RB_GC_GUARD(return_value);
    
  128. Aaron Bartell reporter

    #Good news!
    I was not able to produce the error after 20 minutes of refreshing. Below is the only reference to an error in file /tmp/libdb...:

    % grep -i 'error' /tmp/libdb400_trace_15287
    SQLGetFunctions.15287.1444341763.6.tbeg ---error---
    SQLGetFunctions.15287.1444341763.6.retn SQLRETURN sqlrc 0xfffffffe (-2) SQL_INVALID_HANDLE (SQL_ERROR)
    SQLGetFunctions.15287.1444341763.6.tend ---error---
    SQLDescribeCol.15287.1444341944.156.phex 22513a16 : 6748656c7065724572726f7200350000 >gHelperError.5..<
    SQLDescribeCol.15287.1444341944.156.phex 22513a16 : 6748656c7065724572726f7200350000 >gHelperError.5..<
    SQLDescribeCol.15287.1444341944.156.phex 22513a16 : 6748656c7065724572726f7200350000 >gHelperError.5..<
    SQLDescribeCol.15287.1444341944.156.phex 22513a16 : 6748656c7065724572726f7200350000 >gHelperError.5..<
    SQLDescribeCol.15287.1444341944.156.phex 22513a16 : 6748656c7065724572726f7200350000 >gHelperError.5..<
    SQLDescribeCol.15287.1444341944.156.phex 22513a16 : 6748656c7065724572726f7200350000 >gHelperError.5..<
    SQLDescribeCol.15287.1444341944.156.phex 22513a16 : 6748656c7065724572726f7200350000 >gHelperError.5..<
    SQLDescribeCol.15287.1444341944.156.phex 22513a16 : 6748656c7065724572726f7200350000 >gHelperError.5..<
    SQLBindCol.15287.1444342179.248.phex 2322a310 : 7265736f757263655f6572726f727300 >resource_errors.<
    

    Are there other steps we need to take at this point other than compile a version for distribution? I'd like to put this on RubyGems.org like we did for xmlservice. That way people can get access to our latest work. As we discussed, I will do the compile/distribution vs. you.

  129. Former user Account Deleted

    Well, this was only a test version. That is we neutered statement handle free. We should be more judicious, cleanly, avoid running out of statement handles in final fix.

    I do not want to see 200MB trace, aka, our new trace works too good, perhaps cut/paste 10-20 calls around the error notification, just to look into the box.

  130. Aaron Bartell reporter

    Here is the portion of the trace with the error. Note I copied from the very beginning of the trace through line 256. The error is in the middle.

    Also, here's a portion of the trace from the end of the file in case it helps.

  131. Former user Account Deleted

    Completely benign ... our new 'merged trace', uses unsupported function in SQLGetFunctions 0x3e7 == 999, which is used to decide if we can add script trace data at all. SQLOverrideCCSID400 occurs before the SQL environment is even set, chicken/egg issue that will happen each time started, we will have to look at not asking the question on this API (probably only SQLOverrideCCSID400).

  132. Former user Account Deleted

    Ok, i think you can release this fix "as is". I looked at the ibm_db.c code, and, the customer is able to free statements returned as resources on his own. However, if the customer does not free returned statement handles, well, tough luck, aka, no good place to "baby sit" bad applications, especially Rails applications, because they intentionally hold db2 connection open forever (even if open same profile more than once ... stupid).

    Second, it appears you may be using an older version of the trace libdb400.a, please upgrade from the Yips site, then retry to see if SQLGetFunctions invalid handle goes away.

  133. Aaron Bartell reporter

    Second, it appears you may be using an older version of the trace libdb400.a

    Here is the version I am using and how I prime my shell session before starting the Rails app. It appears I am using the most current version according to what I see on YiPs. Let me know if you'd like me to try something else.

    export LIBPATH=/QOpenSys/download/trace-1.0.6-xlc
    export PASETRACE=/QOpenSys/download/trace-1.0.6-xlc/paseclitrace.ini
    export IBM_DB_GIL="00000000000000000000000000000000000000000000"
    

    Ok, i think you can release this fix "as is".

    Will do. I'd like to run a couple of enhancements past you to get your agreement.

    • 1) Move all files in ruby-ibm_db/IBM_DB_Adapter/ibm_db/ up to top of project. I will use git mv so we retain file history.
    • 2) Go down to one README* file. I will work through them and come up with a single one that addresses our needs.
    • 3) Remove prior version *.gemspec files and resort to the single ibm_db.gemspec (which currently exists). Previous versions exist in commit history so we lose nothing.
    • 4) Publish to rubygems.org as version ibm_db-2.5.15

    On final note, Andrea or PowerRuby, is there anything in here that would keep you from including this version in the PowerRuby Community Edition distribution?

  134. Former user Account Deleted

    1-4) I see no functional reason to change git geometry (move things around). Why take the chance of breaking something just for "pretty". So, no, leave it alone.

    I am not sure about the one error in trace libdb400.a. However, i want to make VERY clear that trace version libdb400.a is NOT to be used in production, or shipped with ibm_db ruby gem. Trace version of libdb400.a is for debug ONLY, there is no dependencies on our fix to ibm_db.

    I don't think you need IBM_DB_GIL. In fact you should re-test without this setting to assure the Ruby GC fix is good.

  135. Former user Account Deleted

    Maybe one extra note for clarity, as mentioned, you need to re-test without trace libdb400.a, and, NO "export" settings (nothing). We need to make sure normal production path has fixed Ruby GC problem.

  136. Former user Account Deleted

    One more thing, leave the version alone. IBM legal thing, fixes are ok, new version is a legal review, aka, another legal review if we change the ibm_db version. Argh, just, just, just, don't ask.

  137. Aaron Bartell reporter

    I see no functional reason to change git geometry (move things around). Why take the chance of breaking something just for "pretty". So, no, leave it alone.

    It was more an effort to follow convention and give clarity, which are both important for community involvement. I will leave it alone.

    However, i want to make VERY clear that trace version libdb400.a is NOT to be used in production, or shipped with ibm_db ruby gem.

    Agreed.

    I don't think you need IBM_DB_GIL. In fact you should re-test without this setting to assure the Ruby GC fix is good.

    The past number of recent tests I've first produced the error without trace, and then once the error was produced I turned on trace to reproduce it. Regardless, I will do another round without trace/exports before packaging it up.

    One more thing, leave the version alone. IBM legal thing, fixes are ok, new version is a legal review, aka, another legal review if we change the ibm_db version. Argh, just, just, just, don't ask.

    Gem versions are how an app differentiates what is used (i.e. specify higher version inGemfile). By not changing the version the probability of accidental usage of old gem goes up. I thought me producing the deliverable addressed this issue.

  138. Former user Account Deleted

    Yes and no, i understand gem version reasons, service and all, but no we can not change the version, or, i really do have to do another review of source code with IBM legal (representative). Oh man, please do not ask any more, i am embarrassed by this cooperate process ...

  139. Aaron Bartell reporter

    Once ibm_db is compiled where are we allowed to put it for distribution? Without being able to differentiate versions I am hesitant to put it on RubyGems.org. Thoughts on putting it in this project's downloads section?

    Andrea, are you still monitoring this thread? Does having the same version affect whether PowerRuby includes this iteration in the distribution?

  140. Former user Account Deleted

    Once you (not i), compile the source to make the gem, you (not i), can do whatever you want with it.

    However, opinion, if you IBM i currently have version of ruby gem ibm_db, i would simply blast over the old version RubyGems.org. To wit, who cares? Akak, someone has a problem, go install the latest from RubyGems.org, easy as pie.

    BTW -- I have no intention of going back to IBM legal review for a new version every ten lines of code (actually this fix removed ten lines of code).

  141. Aaron Bartell reporter

    Akak, someone has a problem, go install the latest from RubyGems.org, easy as pie.

    And that's the issue, if we don't change the version then when someone runs bundle install it will think it already has the right version and not pull the latest. They'd have to do manual installation and I can't imagine that going well for shops that are new(er) to Ruby. Which in turn will have people coming to us asking for support.

    you (not i), can do whatever you want with it.

    Wouldn't that also include publishing to RubyGems.org with the version of my choice? I figure as long as I leave you/IBM out of the process then I am acting entirely on my own and not causing you/IBM liability. Right? I am pushing for this because it is better for the community (and for saving me time).

  142. Former user Account Deleted

    Sorry, no, once you ship a different version of the source, then i have to go back to the IBM legal review. This is why i hesitated to make a fork git account for ibm_db at all. In this case IBM 'approvers' are ok with a version of ibm_db, same as LUW, and ok with 'reasonable' fixes to source version.

    Really, simply a fact of working for IBM ... and ... within IBM OS contribution process. I do not make the IBM OS legal rules, i simply follow the rules.

    So, we had better think of a way to update ibm_db gem without creating a new version.

  143. Former user Account Deleted

    BTW -- if you wish to disagree with IBM OS processes, and, version review rules, you need to talk to a IBM vice president. I, Ranger 'Nobody', have no influence on matters of state (obviously).

  144. Aaron Bartell reporter

    I doubt I could change the mind of a VP either, so I will pass.

    #Distribution Next steps (documenting the how of distribution)...

    To distribute a gem that doesn't need to be compiled by others I need to make it into a "fat binary gem". To accomplish this I needed to install gem-compiler and then run the following command:

    $ gem compile ibm_db-2.5.14.gem
    

    Which produces a file named ibmi_db-2.5.14-powerpc-aix-6.gem (now we know where PowerRuby naming comes from).

    I then uploaded it to this project's download page.

    A user can do wget https://bitbucket.org/litmis/ruby-ibm_db/downloads/ibm_db-2.5.14-powerpc-aix-6.gem and then gem install ./ibm_db-2.5.14-powerpc-aix-6.gem.

    #Future updates We can continue to keep the version/file named the same and differentiate "fixes" via other means (i.e. a fix.txt file or something - your call).

    Thoughts?

  145. Aaron Bartell reporter

    Scratch wget (doesn't work with SSL, silly).

    curl -OkL https://bitbucket.org/litmis/ruby-ibm_db/downloads/ibm_db-2.5.14-powerpc-aix-6.gem
    
  146. Aaron Bartell reporter

    I attempted to install the compiled gem on a machine that only has prV2R0 and it bombed with the following. I then tried rebuilding the gem with prV2R0 in my PATH but that gave the same result.

    $ rails s -p11030
    /PowerRuby/prV2R0/lib/ruby/gems/2.0.0/gems/railties-4.0.12/lib/rails/app_rails_loader.rb:37: warning: Insecure world writable dir /QOpenSys in PATH, mode 042777
    /PowerRuby/prV2R0/lib/ruby/gems/2.0.0/gems/bundler-1.7.6/lib/bundler/runtime.rb:222: warning: Insecure world writable dir /QOpenSys in PATH, mode 042777
    /ruby/gemsets/development-aaron-prV2R0/gems/ibm_db-2.5.14-powerpc-aix-6/lib/ibm_db.rb:1:in `require': load failed - /ruby/gemsets/development-aaron-prV2R0/gems/ibm_db-2.5.14-powerpc-aix-6/lib/ibm_db.so. Please issue below command for detailed reasons: (LoadError)
            /usr/sbin/execerror ruby "30  /ruby/gemsets/development-aaron-prV2R0/gems/ibm_db-2.5.14-powerpc-aix-6/lib/ibm_db.so" "36 ___strcmp 1 /usr/lib/libc.a shr.o" "36 ___strcpy 4 /usr/lib/libc.a shr.o" "2 /ruby/gemsets/development-aaron-prV2R0/gems/ibm_db-2.5.14-powerpc-aix-6/lib/ibm_db.so" "6 8"
            from /ruby/gemsets/development-aaron-prV2R0/gems/ibm_db-2.5.14-powerpc-aix-6/lib/ibm_db.rb:1:in `<top (required)>'
            from /PowerRuby/prV2R0/lib/ruby/gems/2.0.0/gems/bundler-1.7.6/lib/bundler/runtime.rb:76:in `require'
            from /PowerRuby/prV2R0/lib/ruby/gems/2.0.0/gems/bundler-1.7.6/lib/bundler/runtime.rb:76:in `block (2 levels) in require'
            from /PowerRuby/prV2R0/lib/ruby/gems/2.0.0/gems/bundler-1.7.6/lib/bundler/runtime.rb:72:in `each'
            from /PowerRuby/prV2R0/lib/ruby/gems/2.0.0/gems/bundler-1.7.6/lib/bundler/runtime.rb:72:in `block in require'
            from /PowerRuby/prV2R0/lib/ruby/gems/2.0.0/gems/bundler-1.7.6/lib/bundler/runtime.rb:61:in `each'
            from /PowerRuby/prV2R0/lib/ruby/gems/2.0.0/gems/bundler-1.7.6/lib/bundler/runtime.rb:61:in `require'
            from /PowerRuby/prV2R0/lib/ruby/gems/2.0.0/gems/bundler-1.7.6/lib/bundler.rb:133:in `require'
            from /home/aaron/git/myapp/config/application.rb:7:in `<top (required)>'
            from /PowerRuby/prV2R0/lib/ruby/gems/2.0.0/gems/railties-4.0.12/lib/rails/commands.rb:74:in `require'
            from /PowerRuby/prV2R0/lib/ruby/gems/2.0.0/gems/railties-4.0.12/lib/rails/commands.rb:74:in `block in <top (required)>'
            from /PowerRuby/prV2R0/lib/ruby/gems/2.0.0/gems/railties-4.0.12/lib/rails/commands.rb:71:in `tap'
            from /PowerRuby/prV2R0/lib/ruby/gems/2.0.0/gems/railties-4.0.12/lib/rails/commands.rb:71:in `<top (required)>'
            from bin/rails:4:in `require'
            from bin/rails:4:in `<main>'
    <bc.a shr.o" "2 /ruby/gemsets/development-aaron-prV2R0/gems/ibm_db-2.5.14-powerpc-aix-6/lib/ibm_db.so" "6 8"
    Could not load program ruby:
    Symbol resolution failed for /ruby/gemsets/development-aaron-prV2R0/gems/ibm_db-2.5.14-powerpc-aix-6/lib/ibm_db.so because:
            Symbol ___strcmp (number 1) is not exported from dependent
              module /usr/lib/libc.a(shr.o).
            Symbol ___strcpy (number 4) is not exported from dependent
              module /usr/lib/libc.a(shr.o).
    Could not load module /ruby/gemsets/development-aaron-prV2R0/gems/ibm_db-2.5.14-powerpc-aix-6/lib/ibm_db.so.
    System error: Exec format error
    Examine .loader section symbols with the 'dump -Tv' command.
    

    The following produces no results so I am guessing PowerRuby uses the libc.a shipped with PASE:

    $ find /PowerRuby -name 'libc.a'
    $
    

    Any idea on how to fix this?

  147. Former user Account Deleted

    You need to compile the gem with OLDEST possible supported PASE for PowerRuby. I believe PoweRuby runs on V7R1+, so compile your gem on V7R1 machine (and use on all releases IBM i).

  148. Former user Account Deleted

    Here ...

    This is my V7R2 machine ... ok for your gem ...

    bash-3.00$ dump -Tuv /usr/lib/libc.a | grep ___strcpy
    [474]   0x0000fc00    undef   ImpExp     XO EXTref        [noIMid] ___strcpy
    

    From my V7R1 machine ... not work gem ...

    $ dump -Tuv /usr/lib/libc.a | grep ___strcpy
    $ 
    
  149. Aaron Bartell reporter

    You need to compile the gem with OLDEST possible supported PASE for PowerRuby. I believe PoweRuby runs on V7R1+, so compile your gem on V7R1 machine (and use on all releases IBM i).

    That was the issue. I have produced a new gem file and will replace the existing one in the downloads section.

  150. Aaron Bartell reporter

    I am marking this as resolved. I have installed the fix into multiple applications and it has worked successfully.

  151. Log in to comment