Could not find prepared statement with handle error

[radovanradic]

Hello,

Not sure if this is a bug or our issue, just wanted to ask if you have seen something similar. After upgrading to 1.0.1.RELEASE we are getting tests failing for r2dbc mssql

io.r2dbc.mssql.ExceptionFactory$MssqlNonTransientException: Could not find prepared statement with handle 1073741825.

Reverting to 1.0.0.RELEASE fixes the issue. Also reverting only change in this commit for MssqlConnectionConfiguration class also fixes the issue. So it has something to do with the change around preferCursoredExecution but don't see we can do anything in our code to resolve it.
Here is the sample app/test which can be used to reproduce the error. The test is for micronaut r2dbc module that worked previously.

Thanks and let me know if you see we can fix something on our end or this is a bug in latest release of mssql r2dbc.

Thanks,
Radovan

[mp911de]

I need to have a look. Thanks for the reproducer.

[SimenRokaas]

Same as I commented here a couple of days ago, should perhaps have created an issue like this. Thanks for reporting it as a separate issue @radovanradic !

[mp911de]

@SimenRokaas Can you attach debug logs for the io.r2dbc logger?

[SimenRokaas]

Sure

DEBUG io.r2dbc.pool.ConnectionPool - Obtaining new connection from the pool
DEBUG io.r2dbc.mssql.SimpleMssqlStatement - [cid: 0x9] Start direct exchange for SELECT 1
DEBUG i.r.mssql.client.ReactorNettyClient - [cid: 0x9] exchange()
DEBUG io.r2dbc.mssql.QUERY - [cid: 0x9] Executing query: SELECT 1
DEBUG i.r.mssql.client.ReactorNettyClient - [cid: 0x9] exchange(subscribed)
DEBUG i.r.mssql.client.ReactorNettyClient - [cid: 0x9] Initiating exchange
DEBUG i.r.mssql.client.ReactorNettyClient - [cid: 0x9] Request: SQLBatch [sql="SELECT 1"]
DEBUG io.r2dbc.pool.ConnectionPool - Obtaining new connection from the pool
DEBUG io.r2dbc.mssql.MssqlConnection - [cid: 0xa] Creating statement for SQL: [SELECT COUNT(*) AS cnt FROM FormEvent WHERE Status IN (@P0_statuses)]
DEBUG i.r.mssql.ParametrizedMssqlStatement - [cid: 0xa] Start cursored exchange for SELECT COUNT(*) AS cnt FROM FormEvent WHERE Status IN (@P0_statuses) with fetch size 128
DEBUG i.r.mssql.client.ReactorNettyClient - [cid: 0xa] exchange()
DEBUG io.r2dbc.mssql.QUERY - [cid: 0xa] Executing query: SELECT COUNT(*) AS cnt FROM FormEvent WHERE Status IN (@P0_statuses)
DEBUG i.r.mssql.client.ReactorNettyClient - [cid: 0xa] exchange(subscribed)
DEBUG i.r.mssql.client.ReactorNettyClient - [cid: 0xa] Initiating exchange
DEBUG i.r.mssql.client.ReactorNettyClient - [cid: 0xa] Request: RPCRequest [procName='null', procId=4, optionFlags=io.r2dbc.mssql.message.token.RpcRequest$OptionFlags@6387756e, statusFlags=0, parameterDescriptors=[RpcInt [name='null', value=1073741825], RpcInt [name='null', value=0], RpcInt [name='null', value=4], RpcInt [name='null', value=8193], RpcInt [name='null', value=0], EncodedRpcParameter [name='P0_statuses', value=io.r2dbc.mssql.codec.CharacterEncoder$NvarcharEncoded@6a675284]]]
DEBUG i.r.mssql.client.ReactorNettyClient - [cid: 0x9] Response: ColumnMetadataToken [columns=[Column [name='", type=MutableTypeInformation [maxLength=4, lengthStrategy=FIXEDLENTYPE, precision=10, displaySize=11, scale=0, flags=32, serverType=int, userType=0, udtTypeName="null", collation=null, charset=null], table=null]]]
DEBUG io.r2dbc.mssql.DefaultMssqlResult - [cid: 0x9] Creating new result
DEBUG i.r.mssql.client.ReactorNettyClient - [cid: 0x9] Response: io.r2dbc.mssql.message.token.RowToken@122095d5
DEBUG i.r.mssql.client.ReactorNettyClient - [cid: 0x9] Response: DoneToken [done=true, hasCount=true, rowCount=1, hasMore=false, attnAck=false, currentCommand=0]
DEBUG io.r2dbc.mssql.DefaultMssqlResult - [cid: 0x9] Incoming row count: DoneToken [done=true, hasCount=true, rowCount=1, hasMore=false, attnAck=false, currentCommand=0]
DEBUG io.r2dbc.pool.PooledConnection - Releasing connection
DEBUG i.r.mssql.client.ReactorNettyClient - [cid: 0x9] Conversation complete
DEBUG i.r.mssql.client.ReactorNettyClient - [cid: 0xa] Response: ErrorToken [number=8179, state=4, infoClass=16, message='Could not find prepared statement with handle 1073741825.", serverName='a11e255015a3", procName='", lineNumber=16777216]
DEBUG i.r.mssql.client.ReactorNettyClient - [cid: 0xa] Warning: Code [8179] Severity [GENERAL_ERROR]: Could not find prepared statement with handle 1073741825.
DEBUG io.r2dbc.mssql.DefaultMssqlResult - [cid: 0xa] Creating new result
DEBUG i.r.mssql.util.FluxDiscardOnCancel - received cancel signal
DEBUG io.r2dbc.pool.PooledConnection - Releasing connection
DEBUG i.r.mssql.client.ReactorNettyClient - [cid: 0xa] Response: ReturnStatus [status=8179]
DEBUG i.r.mssql.client.ReactorNettyClient - [cid: 0xa] Response: ReturnValue [ordinal=1, parameterName='', value=PooledSlicedByteBuf(ridx: 0, widx: 5, cap: 5/5, unwrapped: PooledUnsafeDirectByteBuf(ridx: 209, widx: 209, cap: 256)), type=MutableTypeInformation [maxLength=4, lengthStrategy=BYTELENTYPE, precision=10, displaySize=11, scale=0, flags=0, serverType=int, userType=0, udtTypeName="null", collation=null, charset=null]]
DEBUG io.r2dbc.mssql.RpcQueryMessageFlow - CursorId: 0
DEBUG i.r.mssql.client.ReactorNettyClient - [cid: 0xa] Response: ReturnValue [ordinal=4, parameterName='', value=PooledSlicedByteBuf(ridx: 0, widx: 5, cap: 5/5, unwrapped: PooledUnsafeDirectByteBuf(ridx: 209, widx: 209, cap: 256)), type=MutableTypeInformation [maxLength=4, lengthStrategy=BYTELENTYPE, precision=10, displaySize=11, scale=0, flags=0, serverType=int, userType=0, udtTypeName="null", collation=null, charset=null]]
DEBUG i.r.mssql.client.ReactorNettyClient - [cid: 0xa] Response: DoneProcToken [done=true, hasCount=false, rowCount=0, hasMore=false, attnAck=false, currentCommand=224]
DEBUG i.r.mssql.client.ReactorNettyClient - [cid: 0xa] Conversation complete

[kschlesselmann]

@mp911de Any news on this? After upgrading to the current Spring Boot Release we experience the same error. Some other tests suddenly run into

Caused by: io.r2dbc.mssql.ExceptionFactory$MssqlNonTransientException: The parameterized query '(@P0_name nvarchar(4000))SELECT attachment.id, attachment.name, ' expects the parameter '@P0_name', which was not supplied.

If I just pin the driver at 1.0.0.RELEASE again everything works fine.

[mp911de]

I think there has been a bug for a longer period of time that now gets visible with the changed cursoring behavior. The JDBC driver attempts a re-prepare upon errors 8179 and 586.

This is what we should attempt as well.

[mp911de]

We now attempt a reprepare when encountering a no prepared statement response from the server. Please retry against the latest 1.0.2 snapshots, available from http://oss.sonatype.org/content/repositories/snapshots.

[kschlesselmann]

@mp911de OK, I cannot reproduce the "handle error" any more. Our tests fail with 1.0.2.BUILD-SNAPSHOT nevertheless. The problem seems to have something to do with concurrency though. If I run the failing tests by themselves they run fine. If I run everything in bulk I (for example) end up with

Caused by: io.r2dbc.mssql.ExceptionFactory$MssqlNonTransientException: The parameterized query '(@P0_name nvarchar(4000))SELECT attachment.id, attachment.name, ' expects the parameter '@P0_name', which was not supplied.

for example. Any suggestions what could go wrong here? Again: 1.0.0.RELEASE is fine.

[mp911de]

@kschlesselmann can you please file a new ticket along with a minimal reproducer?

[kschlesselmann]

@mp911de OK. I'm afraid that'll be not so easy but let's see.

[stephanpelikan]

I have this issue as mentioned in #248 (comment). With the latest SNAPSHOT in use the error is gone.

[sebastian-alfers]

I see a similar "Connection closed" exception (sometimes). Running version 1.0.2.RELEASE and disabled cursored execution.