Simplifying an OpenAPI trace log

Ingres’s OpenAPI C interface can be challenging at times especially when it comes to debugging or reading an API trace. For example, right now I’m trying to debug a problem in the PHP driver for Ingres. For some reason during the tear-down of the request the driver is unable to close a statement. Turning to a level 5 API trace I get this. Which, to be honest has information in there that I don’t exactly need. Specifically I’m not too interested in the calls to IIapi_wait() [1] or the lower level Dispatch() functions. With this in mind using grep I can filter out this “chaff”, and produce a more concise log file:

grep -v "IIapi_wait|Dispatch" api.log

Turning this into:

!IIapi_initAPI: initializing API.
!IIapi_initialize: INGRES API initialized, envHndl = 090F9308
!IIapi_initialize: startup API
!IIapi_initialize: version = 6
!IIapi_initialize: INGRES API initialized, envHndl = 09078018
!IIapi_connect: connect to DBMS Server
!IIapi_connect: envHndl = 09078018, connHndl = 00000000, tranHndl= 00000000
!IIapi_connect: target = @server,tcp_ip,ii[user:secret]::dbname
!IIapi_thread(-1226205472): allocated local storage 091A5E78
!IIapi_appCallback: request completed, status = SUCCESS
!IIapi_setEnvParam: set environment parameter
!IIapi_setEnvParam: envHndl = 09078018
!IIapi_setEnvParam: paramID = 24.
!IIapi_autocommit: set autocommit state
!IIapi_autocommit: connHndl = 091A5960, tranHndl = 00000000
!IIapi_appCallback: request completed, status = SUCCESS
!IIapi_query: starting a query
!IIapi_query: connHndl = 091A5960, tranHndl = 091A69B8, queryType = 0
!IIapi_query: queryText = set session with description='hello'
!IIapi_appCallback: request completed, status = SUCCESS
!IIapi_close: closing a query
!IIapi_close: stmtHndl = 091A8070
!IIapi_appCallback: request completed, status = SUCCESS
!IIapi_query: starting a query
!IIapi_query: connHndl = 091A5960, tranHndl = 091A69B8, queryType = 0
!IIapi_query: queryText = set lockmode session where readlock=nolock
!IIapi_appCallback: request completed, status = SUCCESS
!IIapi_close: closing a query
!IIapi_close: stmtHndl = 091A6580
!IIapi_appCallback: request completed, status = SUCCESS
!IIapi_cancel: cancelling a query
!IIapi_cancel: invalid handle
!IIapi_appCallback: request completed, status = INVALID_HANDLE
!IIapi_close: closing a query
!IIapi_close: invalid statement handle
!IIapi_appCallback: request completed, status = INVALID_HANDLE
!IIapi_autocommit: set autocommit state
!IIapi_autocommit: connHndl = 091A5960, tranHndl = 091A69B8
!IIapi_appCallback: request completed, status = SUCCESS
!IIapi_disconnect: disconnecting a connection
!IIapi_disconnect: connHndl = 091A5960
!IIapi_appCallback: request completed, status = SUCCESS
!IIapi_releaseEnv: Release Environment
!IIapi_releaseEnv: envHndl = 09078018
!IIapi_terminate: shutdown API
!IIapi_releaseEnv: Release Environment
!IIapi_releaseEnv: envHndl = 090F9308
!IIapi_terminate: shutdown API
!IIapi_termAPI: shutting down API completely.
!IIapi_termAPI: API shutdown.

A lot simpler to read – Now I can see that a bad statement handle has been passed to IIapi_cancel() and IIapi_close(). Now I know what the problem is it’s time to find where the statement handle is coming from.

[1] It should be noted that you cannot always discount IIapi_wait() calls. A number of years ago I hit a weird timing issue due to a missing IIapi_wait() call.