Ruby API returns different result based on same SQL but prepared vs execute_direct

[kbachl]

Hi,

following code:

 sql = <<-END_SQL
            select count("ItemCode") from "TEST2024"."OITM" where "ItemCode" =  ?
        END_SQL
        p item_code

        # this won't work, allways returns [0,0]!
        stmt = @@api.hanaclient_prepare @@connection, sql
        _, param = @@api.hanaclient_describe_bind_param(stmt, 0)
        param.set_value(item_code)
        @@api.hanaclient_bind_param(stmt, 0, param)
        _rc = @@api.hanaclient_execute(stmt)
        @@api.hanaclient_fetch_next( stmt )


        puts "R1: " + @@api.hanaclient_get_column(stmt, 0).to_s
        @@api.hanaclient_free_stmt(stmt)


        #This works -> correct results returned:
        sql = ActiveRecord::Base.sanitize_sql([sql, item_code])
        stmt = @@api.hanaclient_execute_direct(@@connection, sql)
        @@api.hanaclient_fetch_next( stmt )
        puts "R2: " +  @@api.hanaclient_get_column(stmt, 0).to_s

whatever I try I allways get a return of array [0,0] in case of my prepared statement compared to the direct executed one that returns the correct and expected data.

Result:

11:38:27 web.1             | "CODE-1"
11:38:27 web.1             | R1: [1, 0]
11:38:27 web.1             | R2: [1, 1]
11:38:27 web.1             | nil
11:38:27 web.1             | "CODE-2"
11:38:27 web.1             | R1: [1, 0]
11:38:27 web.1             | R2: [1, 1]
11:38:27 web.1             | nil
11:38:27 web.1             | "NOTEXISITNG"
11:38:27 web.1             | R1: [1, 0]
11:38:27 web.1             | R2: [1, 0]
11:38:27 web.1             | nil

Im using the latest driver 20.20.20. Any idea what I made wrong in my prepared statement?

[jeff_albion]

Hello,

I can't seem to reproduce this behaviour with a simplified example:

require 'hanaclient'
include HANACLIENT

@@api = HANACLIENT::HANACLIENTInterface.new()
HANACLIENT::API.hanaclient_initialize_interface(@@api)
@@api.hanaclient_init()
@@conn = @@api.hanaclient_new_connection()
@@api.hanaclient_connect(@@conn, "servernode=myserver:30015;UID=myuser;PWD=mypwd")

sql = <<-END_SQL
            select 42 from "SYS"."DUMMY" where 1 = ?
        END_SQL
item_code = 1

stmt = @@api.hanaclient_prepare @@conn, sql
_, param = @@api.hanaclient_describe_bind_param(stmt, 0)
param.set_value(item_code)
@@api.hanaclient_bind_param(stmt, 0, param)
_rc = @@api.hanaclient_execute(stmt)
@@api.hanaclient_fetch_next( stmt )

puts "R1: " + @@api.hanaclient_get_column(stmt, 0).to_s
@@api.hanaclient_free_stmt(stmt)

@@api.hanaclient_disconnect(@@conn)
@@api.hanaclient_free_connection(@@conn)
@@api.hanaclient_fini()
HANACLIENT::API.hanaclient_finalize_interface(@@api)

Can you also run my example and see the correct value?

From your example, are you sure that the value being bound is being found correctly in the table? Have you tried adding SQLDBC Tracing 

to your application to better understand what's happening inside the driver for the bind value and result? You can quickly set environment variables to trace to stdout if that's helpful:

export HDB_SQLDBC_TRACEFILE=stdout
export HDB_SQLDBC_TRACEOPTS=SQL,DEBUG,FLUSH

Best regards,

Jeff

[kbachl]

I made an "Answer" below - seems I cant directly reply to you

[jeff_albion]

Hi @kbachl, thanks for trying the updated instructions. I can see from your trace that the string value isn't bound properly from the ruby level:

10:13:01 web.1             | [SQLDBC] >StringTranslator::translateUTF8Input (2024-05-17 10:13:01.192845)
10:13:01 web.1             | [SQLDBC] data=
10:13:01 web.1             | [SQLDBC] >GenericTranslator::addCharacterData (2024-05-17 10:13:01.192855)
10:13:01 web.1             | [SQLDBC] <=SQLDBC_OK
10:13:01 web.1             | [SQLDBC] <=SQLDBC_OK
10:13:01 web.1             | [SQLDBC] <=SQLDBC_OK
10:13:01 web.1             | [SQLDBC] 1     UTF8          0             0             ''

I had been originally trying Ruby 2.7, but couldn't reproduce the problem:

[SQLDBC] >GenericTranslator::addCharacterData (2024-05-17 16:21:08.715159)
[SQLDBC] <=SQLDBC_OK
[SQLDBC] <=SQLDBC_OK
[SQLDBC] <=SQLDBC_OK
[SQLDBC] 1     UTF8          9             9             'TestValue'

ruby 2.7.6p219 (2022-04-12 revision c9c2245c0a) [x86_64-linux]

After I upgraded to the latest Ruby 3.3, I could then reproduce the problem as you described:

ruby 3.3.1 (2024-04-23 revision c56cd86388) [x86_64-linux]

[SQLDBC] >GenericTranslator::addCharacterData (2024-05-17 16:13:54.026311)
[SQLDBC] <=SQLDBC_OK
[SQLDBC] <=SQLDBC_OK
[SQLDBC] <=SQLDBC_OK
[SQLDBC] 1     UTF8          0             0             ''

I am also noticing these ruby messages in Ruby 3.3:

simple.rb:7: warning: undefining the allocator of T_DATA class DBCAPI::a_hanaclient_connection
simple.rb:14: warning: undefining the allocator of T_DATA class DBCAPI::a_hanaclient_stmt
simple.rb:15: warning: undefining the allocator of T_DATA class DBCAPI::a_hanaclient_bind_data

So it seems like there's a bug with newer Ruby versions here - I have opened an internal bug report to investigate further.

Can you try an older version of Ruby for now?

Note that the official Supported Platforms page only lists up to Ruby 2.7 currently: https://me.sap.com/notes/3447024 

Best regards,

Jeff

[kbachl]

@jeff_albionThanks for the update!

I hardly can go on to ruby 2.7 as I'm doing a current new rails project and ruby 3.1.0 is the new baseline for upcoming rails 7.2, me using ruby 3.3.1.
Beside ruby 2.7 is EOL since 2023-03-31. Since I only need this on some rare occasions (when the SAP B1 ServiceLayer is too slow or can't deliver the complexity of a query well enough) I can go forward with using this with the direct SQL way of using ActiveRecord's base

 sql = ActiveRecord::Base.sanitize_sql([sql, item_code])

 for the time. Yet, it would also be nice if you could do a bug report that an access to a non existing row or column dont lead to a SegFault like in my last post as this is quite annoying in development 🙂

[kbachl]

@jeff_albionThanks for trying to help.

I tried your example and it worked as long as the type was integer. As soon as I changed the SQL to use would use String it broke, see:

...
    sql = <<-END_SQL
            select 42 from "SYS"."DUMMY" where 'TestValue' = ?
        END_SQL
          item_code = 'TestValue'

          stmt = @@api.hanaclient_prepare @@connection, sql
          _, param = @@api.hanaclient_describe_bind_param(stmt, 0)
          param.set_value(item_code)
          @@api.hanaclient_bind_param(stmt, 0, param)
          _rc = @@api.hanaclient_execute(stmt)
          @@api.hanaclient_fetch_next( stmt )

          puts "R1: " + @@api.hanaclient_get_column(stmt, 0).to_s
          @@api.hanaclient_free_stmt(stmt)
...

Here it still should work as 'TestValue' = 'TestValue' would be true, yet it gets not result back:

10:13:01 web.1             | [SQLDBC] SQL COMMAND :             select 42 from "SYS"."DUMMY" where 'TestValue' = ?
10:13:01 web.1             | 
10:13:01 web.1             | [SQLDBC] ENCODING    : UTF8
10:13:01 web.1             | [SQLDBC] >Connection::getClientInfo (2024-05-17 10:13:01.192786)
10:13:01 web.1             | [SQLDBC] <=0x00007e6270061cb8
10:13:01 web.1             | [SQLDBC] >PreparedStatement::resetParametersProcessed (2024-05-17 10:13:01.192788)
10:13:01 web.1             | [SQLDBC] <
10:13:01 web.1             | [SQLDBC] >ParseInfo::selectPhysicalConnection (2024-05-17 10:13:01.192791)
10:13:01 web.1             | [SQLDBC] >Connection::selectPhysicalConnection (2024-05-17 10:13:01.192795)
10:13:01 web.1             | [SQLDBC] locationIndex=4294967295
10:13:01 web.1             | [SQLDBC] isUpdateCommand=0
10:13:01 web.1             | [SQLDBC] >Connection::getPrimaryConnection (2024-05-17 10:13:01.192798)
10:13:01 web.1             | [SQLDBC] <=1
10:13:01 web.1             | [SQLDBC] <=1
10:13:01 web.1             | [SQLDBC] <=1
10:13:01 web.1             | [SQLDBC] >PreparedStatement::resetResults (2024-05-17 10:13:01.192803)
10:13:01 web.1             | [SQLDBC] >Statement::resetResults (2024-05-17 10:13:01.192804)
10:13:01 web.1             | [SQLDBC] clearResultSet=1
10:13:01 web.1             | [SQLDBC] >Connection::getWorkloadReplayContext (2024-05-17 10:13:01.192807)
10:13:01 web.1             | [SQLDBC] m_workloadReplayContext=
10:13:01 web.1             | [SQLDBC] <
10:13:01 web.1             | [SQLDBC] <=SQLDBC_OK
10:13:01 web.1             | [SQLDBC] <=SQLDBC_OK
10:13:01 web.1             | [SQLDBC] STATEMENTID    : STATEMENT[C22CE9B2325B0500(1507648191671490):1]
10:13:01 web.1             | [SQLDBC] INPUT PARAMETERS
10:13:01 web.1             | [SQLDBC] APPLICATION
10:13:01 web.1             | [SQLDBC] INDEX TYPE       AT LENGTH        INDICATOR     DATA
10:13:01 web.1             | [SQLDBC] >PreparedStatement::checkInitParameters (2024-05-17 10:13:01.192815)
10:13:01 web.1             | [SQLDBC] <=SQLDBC_OK
10:13:01 web.1             | [SQLDBC] >Connection::getRequestPacket (2024-05-17 10:13:01.192818)
10:13:01 web.1             | [SQLDBC] packetsize=0
10:13:01 web.1             | [SQLDBC] <=SQLDBC_OK
10:13:01 web.1             | [SQLDBC] >RequestPacket::addSegment (2024-05-17 10:13:01.192821)
10:13:01 web.1             | [SQLDBC] <
10:13:01 web.1             | [SQLDBC] >RoutingInfo::addRoutingInfoPart (2024-05-17 10:13:01.192829)
10:13:01 web.1             | [SQLDBC] <=SQLDBC_OK
10:13:01 web.1             | [SQLDBC] >PreparedStatement::executeFillDirectData (2024-05-17 10:13:01.192833)
10:13:01 web.1             | [SQLDBC] haslobs=0
10:13:01 web.1             | [SQLDBC] startindex=1
10:13:01 web.1             | [SQLDBC] >Translator::translateInput (2024-05-17 10:13:01.192836)
10:13:01 web.1             | [SQLDBC] arrayoffset=0
10:13:01 web.1             | [SQLDBC] rowsize=0
10:13:01 web.1             | [SQLDBC] >StringTranslator::translateUTF8Input (2024-05-17 10:13:01.192845)
10:13:01 web.1             | [SQLDBC] data=
10:13:01 web.1             | [SQLDBC] >GenericTranslator::addCharacterData (2024-05-17 10:13:01.192855)
10:13:01 web.1             | [SQLDBC] <=SQLDBC_OK
10:13:01 web.1             | [SQLDBC] <=SQLDBC_OK
10:13:01 web.1             | [SQLDBC] <=SQLDBC_OK
10:13:01 web.1             | [SQLDBC] 1     UTF8          0             0             ''
10:13:01 web.1             | [SQLDBC] 
10:13:01 web.1             | [SQLDBC] <=SQLDBC_OK
10:13:01 web.1             | [SQLDBC] >Connection::sqlaexecute_clientconnection (2024-05-17 10:13:01.192873)
10:13:01 web.1             | [SQLDBC] >Connection::updateStatementContextInRequest (2024-05-17 10:13:01.192875)
10:13:01 web.1             | [SQLDBC] <=SQLDBC_OK
10:13:01 web.1             | [SQLDBC]   PHYSICAL CONNECTION - [0x00007e62700654c0]  [CONNECTED - COORDINATOR]
10:13:01 web.1             | [SQLDBC]   CONNECTED AT        : 2024-05-17 10:13:01.009213
10:13:01 web.1             | [SQLDBC]   LOCATION            : 192.168.*.*:30015 [192.168.*.*]
10:13:01 web.1             | [SQLDBC]   SERVER CONNECTION ID: 351026
10:13:01 web.1             | [SQLDBC]   CLIENT CONNECTION ID: 1
10:13:01 web.1             | [SQLDBC]   VOLUME ID           : 3
10:13:01 web.1             | [SQLDBC]   SESSION ID          : 1647312013039303
10:13:01 web.1             | [SQLDBC]   LAST SEND TIME      : 2024-05-17 10:13:01.141457
10:13:01 web.1             | [SQLDBC]   LAST RECEIVE TIME   : 2024-05-17 10:13:01.192421
10:13:01 web.1             | [SQLDBC] CONNECTION OBJECT : [0x00007e6270061950]
10:13:01 web.1             | [SQLDBC] >SimpleClientSocket::doPollBeforeSendToDetectSocketDead (2024-05-17 10:13:01.192891)
10:13:01 web.1             | [SQLDBC] <
10:13:01 web.1             | [SQLDBC] SEND TIME: 151 USEC, MESSAGE: EXECUTE
10:13:01 web.1             | [SQLDBC] >SocketCommunication::receive (2024-05-17 10:13:01.193060)
10:13:01 web.1             | [SQLDBC] <
10:13:01 web.1             | [SQLDBC] RECV TIME: 48413 USEC
10:13:01 web.1             | [SQLDBC] >Connection::doProcessReply (2024-05-17 10:13:01.241524)
10:13:01 web.1             | [SQLDBC] >ReplySegment::getSQLDiag (2024-05-17 10:13:01.241528)
10:13:01 web.1             | [SQLDBC] <=false
10:13:01 web.1             | [SQLDBC] >Connection::updateTopology (2024-05-17 10:13:01.241532)
10:13:01 web.1             | [SQLDBC] <=SQLDBC_OK
10:13:01 web.1             | [SQLDBC] >Connection::updateSessionVariableCache (2024-05-17 10:13:01.241535)
10:13:01 web.1             | [SQLDBC] <=SQLDBC_OK
10:13:01 web.1             | [SQLDBC] >Connection::processImplicitXASession (2024-05-17 10:13:01.241540)
10:13:01 web.1             | [SQLDBC] requestMessageType=EXECUTE
10:13:01 web.1             | [SQLDBC] <=SQLDBC_OK
10:13:01 web.1             | [SQLDBC] >Connection::updateTransactionStatus (2024-05-17 10:13:01.241544)
10:13:01 web.1             | [SQLDBC] connectionId=1
10:13:01 web.1             | [SQLDBC] action=TA_READTRANS
10:13:01 web.1             | [SQLDBC] TRANSACTION ACTION TA_READTRANS
10:13:01 web.1             | [SQLDBC] TRANSACTION:
10:13:01 web.1             | [SQLDBC]   STATE: READ TRANSACTION
10:13:01 web.1             | [SQLDBC]   PRIMARY: 1
10:13:01 web.1             | [SQLDBC]   TRANSACTION MEMBERS (READ): [1]
10:13:01 web.1             | [SQLDBC]   TRANSACTION MEMBERS (WRITE): []
10:13:01 web.1             | [SQLDBC]   TRANSACTION MEMBERS (WRITE CANDIDATE): []
10:13:01 web.1             | [SQLDBC]   TRANSACTION MEMBERS (WRITE TXN AS OF LAST REPLY) : []
10:13:01 web.1             | [SQLDBC]   HINT ROUTED CONNECTIONS: []
10:13:01 web.1             | [SQLDBC] TRANSACTION UPDATED:
10:13:01 web.1             | [SQLDBC] TRANSACTION:
10:13:01 web.1             | [SQLDBC]   STATE: READ TRANSACTION
10:13:01 web.1             | [SQLDBC]   PRIMARY: 1
10:13:01 web.1             | [SQLDBC]   TRANSACTION MEMBERS (READ): [1]
10:13:01 web.1             | [SQLDBC]   TRANSACTION MEMBERS (WRITE): []
10:13:01 web.1             | [SQLDBC]   TRANSACTION MEMBERS (WRITE CANDIDATE): []
10:13:01 web.1             | [SQLDBC]   TRANSACTION MEMBERS (WRITE TXN AS OF LAST REPLY) : []
10:13:01 web.1             | [SQLDBC]   HINT ROUTED CONNECTIONS: []
10:13:01 web.1             | [SQLDBC] <=SQLDBC_OK
10:13:01 web.1             | [SQLDBC] >Connection::updateStatementContextFromReply (2024-05-17 10:13:01.241559)
10:13:01 web.1             | [SQLDBC] <=SQLDBC_OK
10:13:01 web.1             | [SQLDBC] <=SQLDBC_OK
10:13:01 web.1             | [SQLDBC] <=SQLDBC_OK
10:13:01 web.1             | [SQLDBC] SERVER STATISTICS UPDATE OF [0x00007e627006a3a0]
10:13:01 web.1             | [SQLDBC]   PROCESSING TIME INCREASED TO 170 BY 170 USEC
10:13:01 web.1             | [SQLDBC]   CPU TIME INCREASED TO 99 BY 99 USEC
10:13:01 web.1             | [SQLDBC]   PEAK MEMORY USAGE INCREASED TO 0 BY 0 BYTES
10:13:01 web.1             | [SQLDBC] >Statement::parseResult (2024-05-17 10:13:01.241573)
10:13:01 web.1             | [SQLDBC] >Connection::getWorkloadReplayContext (2024-05-17 10:13:01.241575)
10:13:01 web.1             | [SQLDBC] m_workloadReplayContext=
10:13:01 web.1             | [SQLDBC] <
10:13:01 web.1             | [SQLDBC] RESULTSET ID:RESULT[C22CE9B2325B0500:1]
10:13:01 web.1             | [SQLDBC] parseResult parsing ResultSet
10:13:01 web.1             | [SQLDBC] *** ROW NOT FOUND ***

So we end up in a SegFault if I try to access a non existing Row that should be here:

10:13:01 web.1             | [SQLDBC] ::FETCH NEXT SQLCURS_1 RESULT[C22CE9B2325B0500:1] [0x00007e627006bbb0] 2024-05-17 10:13:01.241744
10:13:01 web.1             | [SQLDBC] >ResultSet::assertNotClosed (2024-05-17 10:13:01.241745)
10:13:01 web.1             | [SQLDBC] <=SQLDBC_OK
10:13:01 web.1             | [SQLDBC] >ResultSet::executeFetchNext (2024-05-17 10:13:01.241747)
10:13:01 web.1             | [SQLDBC] >ResultSet::assertValid (2024-05-17 10:13:01.241748)
10:13:01 web.1             | [SQLDBC] <=SQLDBC_OK
10:13:01 web.1             | [SQLDBC] <=SQLDBC_NO_DATA_FOUND
10:13:01 web.1             | [SQLDBC] <=SQLDBC_NO_DATA_FOUND
10:13:01 web.1             | [SQLDBC] >ResultSet::getResultCount (2024-05-17 10:13:01.241751)
10:13:01 web.1             | [SQLDBC] 
10:13:01 web.1             | [SQLDBC] ::GET RESULT COUNT SQLCURS_1 RESULT[C22CE9B2325B0500:1] [0x00007e627006bbb0]
10:13:01 web.1             | [SQLDBC] COUNT:0
10:13:01 web.1             | [SQLDBC] >ResultSet::assertValid (2024-05-17 10:13:01.241753)
10:13:01 web.1             | [SQLDBC] <=SQLDBC_OK
10:13:01 web.1             | [SQLDBC] <=0
10:13:01 web.1             | [SQLDBC] >ConnectionItem::applicationCheckWarnings (2024-05-17 10:13:01.241756)
10:13:01 web.1             | [SQLDBC] ::APPLICATION CHECKING WARNINGS ON CONNECTIONITEM [0x00007e627006bbb0]
10:13:01 web.1             | [SQLDBC] m_diag.warns=
10:13:01 web.1             | [SQLDBC] <
10:13:01 web.1             | [SQLDBC] >ConnectionItem::applicationCheckError (2024-05-17 10:13:01.241761)
10:13:01 web.1             | [SQLDBC] ::APPLICATION CHECKING ERROR ON CONNECTIONITEM [0x00007e627006bbb0]
10:13:01 web.1             | [SQLDBC] m_diag.errs=
10:13:01 web.1             | [SQLDBC] <
10:13:01 web.1             | /...REDACTED.../hana/hana_query.rb:100: [BUG] Segmentation fault at 0x0000000000000010
10:13:01 web.1             | ruby 3.3.1 (2024-04-23 revision c56cd86388) [x86_64-linux]

And its libSQLDBCHDB 2.20.20.1712178305  version exactly.