java sql-server hibernate c3p0 mssql-jdbc

Hibernate with sql server retrieving data Encountered unexpected unknown token

Using c3p0 0.9.2.1, hibernate 4.2.21, JBoss AS 7.1.1 and connecting with Microsoft SQL Server 2014 - 12.0.2000.8 (X64).

mssql-jdbc 6.2.2 (I tested 6.4.0 for doubt but we are using 6.2.2) is used for JRE7 support.

Scenario

Retrieving data from a table as multiple rows but NOT at once. It's simply a loop and each time a row retrieved and finally they put in HashMap.

Problem & Output

After long investigation and debugging I found out that the problem scope related with two columns in the table. One is VARBINARY(MAX) called signature and the other is VARCHAR(1024) called status. If both of these columns have a value on a row, this exception occurs on retrieving the next row. If any of them is set to null, all is good. No matter the length of the value in them.

Tries so far

Changing the columns order making the VARCHARcolumn is the last cloumn
Changing the columns order making the VARBINARY column is the last cloumn
Changing the length (VARBINARY to 8000 and VARCHAR to 50)
Setting values on other columns with similar or larger length
Logging org.hibernate.session object methods isConnected() and isOpen() and until the exception is thrown, the output was always true for both

Questions

What does that exception means ? Specially that sql server logging doesn't show anything about it !!

Why it's happening and what might be the cause of this ?

   18:53:12,294 SEVERE [com.microsoft.sqlserver.jdbc.internals.TDS.TOKEN]
(http-localhost-127.0.0.1-8080-6) ConnectionID:24 ClientConnectionId:
5bbf35a7-2a3c-4fb5-845a-bbd81d2739ef: getNextResult: Encountered
unexpected unknown token (0x1)
    18:53:12,296 SEVERE [com.microsoft.sqlserver.jdbc.internals.TDS.Reader]
(http-localhost-127.0.0.1-8080-6) ConnectionID:24 ClientConnectionId:
5bbf35a7-2a3c-4fb5-845a-bbd81d2739ef got unexpected value in TDS
response at offset:1158
    18:53:12,300 ERROR [stderr] (http-localhost-127.0.0.1-8080-6) java.lang.reflect.InvocationTargetException

    18:53:12,300 ERROR [stderr] (http-localhost-127.0.0.1-8080-6)   at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

    18:53:12,301 ERROR [stderr] (http-localhost-127.0.0.1-8080-6)   at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)

    18:53:12,301 ERROR [stderr] (http-localhost-127.0.0.1-8080-6)   at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)

    18:53:12,302 ERROR [stderr] (http-localhost-127.0.0.1-8080-6)   at java.lang.reflect.Method.invoke(Unknown Source)
.
.
    18:53:12,304 ERROR [stderr] (http-localhost-127.0.0.1-8080-6)   at org.apache.struts.action.RequestProcessor.processActionPerform(RequestProcessor.java:431)

    18:53:12,305 ERROR [stderr] (http-localhost-127.0.0.1-8080-6)   at org.apache.struts.action.RequestProcessor.process(RequestProcessor.java:236)

    18:53:12,306 ERROR [stderr] (http-localhost-127.0.0.1-8080-6)   at org.apache.struts.action.ActionServlet.process(ActionServlet.java:1196)

    18:53:12,307 ERROR [stderr] (http-localhost-127.0.0.1-8080-6)   at org.apache.struts.action.ActionServlet.doPost(ActionServlet.java:432)

    18:53:12,308 ERROR [stderr] (http-localhost-127.0.0.1-8080-6)   at javax.servlet.http.HttpServlet.service(HttpServlet.java:754)

    18:53:12,309 ERROR [stderr] (http-localhost-127.0.0.1-8080-6)   at javax.servlet.http.HttpServlet.service(HttpServlet.java:847)

    18:53:12,309 ERROR [stderr] (http-localhost-127.0.0.1-8080-6)   at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:329)

    18:53:12,310 ERROR [stderr] (http-localhost-127.0.0.1-8080-6)   at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:248)

.
.
    18:53:12,312 ERROR [stderr] (http-localhost-127.0.0.1-8080-6)   at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:280)

    18:53:12,312 ERROR [stderr] (http-localhost-127.0.0.1-8080-6)   at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:248)

.
.

    18:53:12,314 ERROR [stderr] (http-localhost-127.0.0.1-8080-6)   at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:280)

    18:53:12,314 ERROR [stderr] (http-localhost-127.0.0.1-8080-6)   at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:248)

.
.   
    18:53:12,316 ERROR [stderr] (http-localhost-127.0.0.1-8080-6)   at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:280)

    18:53:12,316 ERROR [stderr] (http-localhost-127.0.0.1-8080-6)   at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:248)

    18:53:12,317 ERROR [stderr] (http-localhost-127.0.0.1-8080-6)   at org.apache.catalina.filters.SetCharacterEncodingFilter.doFilter(SetCharacterEncodingFilter.java:101)

    18:53:12,318 ERROR [stderr] (http-localhost-127.0.0.1-8080-6)   at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:280)

    18:53:12,318 ERROR [stderr] (http-localhost-127.0.0.1-8080-6)   at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:248)

    18:53:12,319 ERROR [stderr] (http-localhost-127.0.0.1-8080-6)   at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:275)

    18:53:12,320 ERROR [stderr] (http-localhost-127.0.0.1-8080-6)   at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:161)

    18:53:12,320 ERROR [stderr] (http-localhost-127.0.0.1-8080-6)   at org.jboss.as.web.security.SecurityContextAssociationValve.invoke(SecurityContextAssociationValve.java:153)

    18:53:12,321 ERROR [stderr] (http-localhost-127.0.0.1-8080-6)   at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:155)

    18:53:12,322 ERROR [stderr] (http-localhost-127.0.0.1-8080-6)   at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)

    18:53:12,322 ERROR [stderr] (http-localhost-127.0.0.1-8080-6)   at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)

    18:53:12,323 ERROR [stderr] (http-localhost-127.0.0.1-8080-6)   at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:368)

    18:53:12,324 ERROR [stderr] (http-localhost-127.0.0.1-8080-6)   at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:877)

    18:53:12,325 ERROR [stderr] (http-localhost-127.0.0.1-8080-6)   at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:671)

    18:53:12,326 ERROR [stderr] (http-localhost-127.0.0.1-8080-6)   at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:930)

    18:53:12,327 ERROR [stderr] (http-localhost-127.0.0.1-8080-6)   at java.lang.Thread.run(Unknown Source)

    18:53:12,328 ERROR [stderr] (http-localhost-127.0.0.1-8080-6) Caused by: org.hibernate.exception.GenericJDBCException: could not
extract ResultSet

    18:53:12,329 ERROR [stderr] (http-localhost-127.0.0.1-8080-6)   at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:54)

    18:53:12,330 ERROR [stderr] (http-localhost-127.0.0.1-8080-6)   at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:124)

    18:53:12,332 ERROR [stderr] (http-localhost-127.0.0.1-8080-6)   at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:109)

    18:53:12,333 ERROR [stderr] (http-localhost-127.0.0.1-8080-6)   at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.extract(ResultSetReturnImpl.java:88)

    18:53:12,335 ERROR [stderr] (http-localhost-127.0.0.1-8080-6)   at org.hibernate.loader.Loader.getResultSet(Loader.java:2062)

    18:53:12,336 ERROR [stderr] (http-localhost-127.0.0.1-8080-6)   at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1859)

    18:53:12,337 ERROR [stderr] (http-localhost-127.0.0.1-8080-6)   at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1838)

    18:53:12,338 ERROR [stderr] (http-localhost-127.0.0.1-8080-6)   at org.hibernate.loader.Loader.doQuery(Loader.java:906)

    18:53:12,339 ERROR [stderr] (http-localhost-127.0.0.1-8080-6)   at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:348)

    18:53:12,340 ERROR [stderr] (http-localhost-127.0.0.1-8080-6)   at org.hibernate.loader.Loader.doList(Loader.java:2550)

    18:53:12,340 ERROR [stderr] (http-localhost-127.0.0.1-8080-6)   at org.hibernate.loader.Loader.doList(Loader.java:2536)

    18:53:12,341 ERROR [stderr] (http-localhost-127.0.0.1-8080-6)   at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2366)

    18:53:12,342 ERROR [stderr] (http-localhost-127.0.0.1-8080-6)   at org.hibernate.loader.Loader.list(Loader.java:2361)

    18:53:12,342 ERROR [stderr] (http-localhost-127.0.0.1-8080-6)   at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:495)

    18:53:12,343 ERROR [stderr] (http-localhost-127.0.0.1-8080-6)   at org.hibernate.hql.internal.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:357)

    18:53:12,343 ERROR [stderr] (http-localhost-127.0.0.1-8080-6)   at org.hibernate.engine.query.spi.HQLQueryPlan.performList(HQLQueryPlan.java:198)

    18:53:12,344 ERROR [stderr] (http-localhost-127.0.0.1-8080-6)   at org.hibernate.internal.SessionImpl.list(SessionImpl.java:1230)

    18:53:12,345 ERROR [stderr] (http-localhost-127.0.0.1-8080-6)   at org.hibernate.internal.QueryImpl.list(QueryImpl.java:101)

    18:53:12,345 ERROR [stderr] (http-localhost-127.0.0.1-8080-6)   at org.hibernate.internal.AbstractQueryImpl.uniqueResult(AbstractQueryImpl.java:909)

.
.

    18:53:12,350 ERROR [stderr] (http-localhost-127.0.0.1-8080-6)   ... 38 more

    18:53:12,351 ERROR [stderr] (http-localhost-127.0.0.1-8080-6) Caused by: com.microsoft.sqlserver.jdbc.SQLServerException: The
connection is closed.

    18:53:12,351 ERROR [stderr] (http-localhost-127.0.0.1-8080-6)   at com.microsoft.sqlserver.jdbc.SQLServerException.makeFromDriverError(SQLServerException.java:228)

    18:53:12,352 ERROR [stderr] (http-localhost-127.0.0.1-8080-6)   at com.microsoft.sqlserver.jdbc.SQLServerConnection.checkClosed(SQLServerConnection.java:1007)

    18:53:12,353 ERROR [stderr] (http-localhost-127.0.0.1-8080-6)   at com.microsoft.sqlserver.jdbc.SQLServerStatement.checkClosed(SQLServerStatement.java:1024)

    18:53:12,353 ERROR [stderr] (http-localhost-127.0.0.1-8080-6)   at com.microsoft.sqlserver.jdbc.SQLServerStatement.executeStatement(SQLServerStatement.java:198)

    18:53:12,354 ERROR [stderr] (http-localhost-127.0.0.1-8080-6)   at com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement.executeQuery(SQLServerPreparedStatement.java:401)

    18:53:12,355 ERROR [stderr] (http-localhost-127.0.0.1-8080-6)   at com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeQuery(NewProxyPreparedStatement.java:116)

    18:53:12,355 ERROR [stderr] (http-localhost-127.0.0.1-8080-6)   at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.extract(ResultSetReturnImpl.java:79)

    18:53:12,356 ERROR [stderr] (http-localhost-127.0.0.1-8080-6)   ... 59 more

Solution

The following solved the retrieval problem and it showed at some submitting lines (inserting and flushing). It seems that retrieving data from the database to the driver is too much because VARBINARY maps to LOB in Java and being large objects opens stream which is not closed any time soon until another retrieval hits the database and driver which causes this issue. Here is the solution

What's solved the problem if retrieval the data is using cursor JDBC property. As Microsoft team on github cleared, the exception thrown directly from the JDBC driver and provided a sample code that is working, I've failed (until this moment) to replicate the issue.

Using cursor is simply adding selectMethod=cursor to the JDBC url. To fully understands what this option does and how it effects the retrieval of data specially LOB types kindly refer to this and this documentation and article.

From Microsoft documentation

selectMethod, String, ["direct" | "cursor"], default is direct

If this property is set to "cursor," a database cursor is created for each query created on the connection for TYPE_FORWARD_ONLY and CONCUR_READ_ONLY cursors. This property is typically required only if the application generates large result sets that cannot be fully contained in client memory. When this property is set to "cursor," only a limited number of result set rows are retained in client memory.

The default behavior is that all result set rows are retained in client memory. This behavior provides the fastest performance when the application is processing all rows.

From the question and answer article

Some questions to consider:

Does the application use scrollable result sets, forward only result sets or some of both? If scrollable, do they fetch all of the data or only scroll to and fetch some of the rows?

Are the result sets generated small or large? This includes number of rows and columns as well as the data contained there in(namely, are there any LOBs)?

Is the application doing transactional work or only operating in auto commit mode?

Does the application ever have more than one result set open at a time on a single connection?

The answers to these questions should help decide which connection parameter is best for the application. First off be aware that eliminating the option from your connection URL altogether is that same as setting the option to “direct” since “direct” is the default setting.

Next, take a look at our description of this option from the JDBC User’s Guide and Reference Manual. Here are some of the key points in this description:

A hint to the driver that determines whether the driver requests a database cursor for Select statements. Performance and behavior of the driver are affected by this property, which is defined as a hint because the driver may not always be able to satisfy the requested method.

If set to direct (the default), the database server sends the complete result set in a single response to the driver when responding to a query. A server-side database cursor is not created if the requested result set type is a forward-only result set. Typically, responses are not cached by the driver. Using this method, the driver must process the entire response to a query before another query is submitted. If another query is submitted (using a different statement on the same connection, for example), the driver caches the response to the first query before submitting the second query. Typically, the direct method performs better than the cursor method.

If set to cursor, a server-side cursor is requested. When returning forward-only result sets, the rows are retrieved from the server in blocks. The setFetchSize() method can be used to control the number of rows that are retrieved for each request when forward-only result sets are returned. Performance tests show that, when returning forward-only result sets, the value of Statement.setFetchSize() significantly impacts performance. There is no simple rule for determining the setFetchSize() value that you should use. We recommend that you experiment with different setFetchSize() values to determine which value gives the best performance for your application. The cursor method is useful for queries that produce a large amount of data, particularly if multiple open result sets are used.

Consider this excerpt from the Performance Considerations section of the User Guide and Reference Manual:

SelectMethod: In most cases, using server-side database cursors impacts performance negatively. However, if the following variables are true for the application, the best setting for this property is cursor, which means use server-side database cursors:

Your application contains queries that retrieve large amounts of data.

Your application executes a SQL statement before processing or closing a previous large result set and does this multiple times.

Large result sets returned by your application use forward-only cursors.