[JBoss JIRA] (TEIID-5183) NPE in Swagger translator
by dalex dalex (JIRA)
[ https://issues.jboss.org/browse/TEIID-5183?page=com.atlassian.jira.plugin... ]
dalex dalex edited comment on TEIID-5183 at 12/20/17 10:58 AM:
---------------------------------------------------------------
Hi [~shawkins] thx a lot for the quick fix but it works for http://api.apis.guru/v2/specs/azure.com/redis/2017-10-01/ endpoint but doesn't work for the following ones (I applied all changes from the issue):
http://api.apis.guru/v2/specs/deutschebahn.com/fahrplan/v1/
http://api.apis.guru/v2/specs/googleapis.com/doubleclicksearch/v2/
http://api.apis.guru/v2/specs/magento.com/2.1/
let me demonstrate you stacktraces here for every endpoint:
1. http://api.apis.guru/v2/specs/deutschebahn.com/fahrplan/v1/ teiid throws out again NPE
{code:noformat}
2017-12-20 16:29:10,238 WARN [org.teiid.RUNTIME] (Worker1_async-teiid-threads1) TEIID50036 VDB test.1 model "mswagger" metadata failed to load. Reason:java.lang.NullPointerExceptio
n: java.lang.NullPointerException
at org.teiid.metadata.MetadataFactory.setUUID(MetadataFactory.java:155)
at org.teiid.metadata.MetadataFactory.addProcedure(MetadataFactory.java:403)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.addProcedure(SwaggerMetadataProcessor.java:240)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.process(SwaggerMetadataProcessor.java:199)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.process(SwaggerMetadataProcessor.java:67)
at org.teiid.translator.ExecutionFactory.getMetadata(ExecutionFactory.java:961)
at org.teiid.query.metadata.NativeMetadataRepository.getMetadata(NativeMetadataRepository.java:96)
at org.teiid.query.metadata.NativeMetadataRepository.loadMetadata(NativeMetadataRepository.java:62)
at org.teiid.query.metadata.ChainingMetadataRepository.loadMetadata(ChainingMetadataRepository.java:55)
at org.teiid.jboss.VDBService$6.run(VDBService.java:341)
at org.teiid.jboss.VDBService$7.run(VDBService.java:392)
at org.teiid.dqp.internal.process.DQPWorkContext.runInContext(DQPWorkContext.java:284)
at org.teiid.dqp.internal.process.ThreadReuseExecutor$RunnableWrapper.run(ThreadReuseExecutor.java:119)
at org.teiid.dqp.internal.process.ThreadReuseExecutor$3.run(ThreadReuseExecutor.java:210)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
{code}
2. http://api.apis.guru/v2/specs/googleapis.com/doubleclicksearch/v2/ teiid throws out NPE but because of another circumstances:
{code:noformat}
2017-12-20 16:47:38,151 WARN [org.teiid.RUNTIME] (Worker1_async-teiid-threads1) TEIID50036 VDB test.1 model "mswagger" metadata failed to load. Reason:java.lang.NullPointerExceptio
n: java.lang.NullPointerException
at org.teiid.translator.swagger.SwaggerMetadataProcessor$3.execute(SwaggerMetadataProcessor.java:463)
at org.teiid.translator.swagger.SwaggerMetadataProcessor$2.visit(SwaggerMetadataProcessor.java:389)
at org.teiid.translator.swagger.PropertyVisitor.accept(PropertyVisitor.java:48)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.walkProperties(SwaggerMetadataProcessor.java:438)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.access$300(SwaggerMetadataProcessor.java:67)
at org.teiid.translator.swagger.SwaggerMetadataProcessor$2.visit(SwaggerMetadataProcessor.java:395)
at org.teiid.translator.swagger.PropertyVisitor.accept(PropertyVisitor.java:48)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.walkProperties(SwaggerMetadataProcessor.java:438)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.addProcedureParameters(SwaggerMetadataProcessor.java:482)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.addProcedure(SwaggerMetadataProcessor.java:254)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.process(SwaggerMetadataProcessor.java:199)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.process(SwaggerMetadataProcessor.java:67)
at org.teiid.translator.ExecutionFactory.getMetadata(ExecutionFactory.java:961)
at org.teiid.query.metadata.NativeMetadataRepository.getMetadata(NativeMetadataRepository.java:96)
at org.teiid.query.metadata.NativeMetadataRepository.loadMetadata(NativeMetadataRepository.java:62)
at org.teiid.query.metadata.ChainingMetadataRepository.loadMetadata(ChainingMetadataRepository.java:55)
at org.teiid.jboss.VDBService$6.run(VDBService.java:341)
at org.teiid.jboss.VDBService$7.run(VDBService.java:392)
at org.teiid.dqp.internal.process.DQPWorkContext.runInContext(DQPWorkContext.java:284)
at org.teiid.dqp.internal.process.ThreadReuseExecutor$RunnableWrapper.run(ThreadReuseExecutor.java:119)
at org.teiid.dqp.internal.process.ThreadReuseExecutor$3.run(ThreadReuseExecutor.java:210)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
{code}
3. http://api.apis.guru/v2/specs/magento.com/2.1/ teiid throws out StackOverflowError, there is a cycle:
{code:noformat}
2017-12-20 16:51:03,475 ERROR [org.teiid.RUNTIME] (Worker1) TEIID30021 Uncaught exception processing work: java.lang.StackOverflowError
at org.teiid.metadata.ColumnSet.getColumnByName(ColumnSet.java:59)
at org.teiid.metadata.MetadataFactory.addColumn(MetadataFactory.java:197)
at org.teiid.metadata.MetadataFactory.addProcedureResultSetColumn(MetadataFactory.java:453)
at org.teiid.translator.swagger.SwaggerMetadataProcessor$1.execute(SwaggerMetadataProcessor.java:286)
at org.teiid.translator.swagger.SwaggerMetadataProcessor$2.visit(SwaggerMetadataProcessor.java:383)
at org.teiid.translator.swagger.PropertyVisitor.accept(PropertyVisitor.java:58)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.walkProperties(SwaggerMetadataProcessor.java:438)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.access$300(SwaggerMetadataProcessor.java:67)
at org.teiid.translator.swagger.SwaggerMetadataProcessor$2.visit(SwaggerMetadataProcessor.java:403)
at org.teiid.translator.swagger.PropertyVisitor.accept(PropertyVisitor.java:48)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.walkProperties(SwaggerMetadataProcessor.java:438)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.access$300(SwaggerMetadataProcessor.java:67)
at org.teiid.translator.swagger.SwaggerMetadataProcessor$2.visit(SwaggerMetadataProcessor.java:403)
at org.teiid.translator.swagger.PropertyVisitor.accept(PropertyVisitor.java:48)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.walkProperties(SwaggerMetadataProcessor.java:438)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.access$300(SwaggerMetadataProcessor.java:67)
at org.teiid.translator.swagger.SwaggerMetadataProcessor$2.visit(SwaggerMetadataProcessor.java:403)
at org.teiid.translator.swagger.PropertyVisitor.accept(PropertyVisitor.java:48)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.walkProperties(SwaggerMetadataProcessor.java:438)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.access$300(SwaggerMetadataProcessor.java:67)
at org.teiid.translator.swagger.SwaggerMetadataProcessor$2.visit(SwaggerMetadataProcessor.java:403)
at org.teiid.translator.swagger.PropertyVisitor.accept(PropertyVisitor.java:48)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.walkProperties(SwaggerMetadataProcessor.java:438)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.access$300(SwaggerMetadataProcessor.java:67)
at org.teiid.translator.swagger.SwaggerMetadataProcessor$2.visit(SwaggerMetadataProcessor.java:403)
at org.teiid.translator.swagger.PropertyVisitor.accept(PropertyVisitor.java:48)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.walkProperties(SwaggerMetadataProcessor.java:438)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.access$300(SwaggerMetadataProcessor.java:67)
at org.teiid.translator.swagger.SwaggerMetadataProcessor$2.visit(SwaggerMetadataProcessor.java:403)
at org.teiid.translator.swagger.PropertyVisitor.accept(PropertyVisitor.java:48)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.walkProperties(SwaggerMetadataProcessor.java:438)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.access$300(SwaggerMetadataProcessor.java:67)
at org.teiid.translator.swagger.SwaggerMetadataProcessor$2.visit(SwaggerMetadataProcessor.java:403)
at org.teiid.translator.swagger.PropertyVisitor.accept(PropertyVisitor.java:48)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.walkProperties(SwaggerMetadataProcessor.java:438)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.access$300(SwaggerMetadataProcessor.java:67)
at org.teiid.translator.swagger.SwaggerMetadataProcessor$2.visit(SwaggerMetadataProcessor.java:403)
at org.teiid.translator.swagger.PropertyVisitor.accept(PropertyVisitor.java:48)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.walkProperties(SwaggerMetadataProcessor.java:438)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.access$300(SwaggerMetadataProcessor.java:67)
at org.teiid.translator.swagger.SwaggerMetadataProcessor$2.visit(SwaggerMetadataProcessor.java:403)
at org.teiid.translator.swagger.PropertyVisitor.accept(PropertyVisitor.java:48)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.walkProperties(SwaggerMetadataProcessor.java:438)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.access$300(SwaggerMetadataProcessor.java:67)
at org.teiid.translator.swagger.SwaggerMetadataProcessor$2.visit(SwaggerMetadataProcessor.java:403)
at org.teiid.translator.swagger.PropertyVisitor.accept(PropertyVisitor.java:48)
{code}
Another thing, teiid at the moment uses the following swagger versions according to the root pom.xml:
<version.swagger-parser>1.0.10</version.swagger-parser>
<version.io.swagger>1.5.8</version.io.swagger>
but these libraries are being actively changed. The latest stable versions for io.swagger is 1.5.17 and for swagger-parser is 1.0.33. Can these versions be updated as well?
was (Author: dalex005):
Hi [~shawkins] thx a lot for the quick fix but it works for http://api.apis.guru/v2/specs/azure.com/redis/2017-10-01/ endpoint but doesn't work for the following ones (I applied all changes from the issue):
http://api.apis.guru/v2/specs/deutschebahn.com/fahrplan/v1/
http://api.apis.guru/v2/specs/googleapis.com/doubleclicksearch/v2/
http://api.apis.guru/v2/specs/magento.com/2.1/
let me demonstrate you stacktraces here for every endpoint:
1. http://api.apis.guru/v2/specs/deutschebahn.com/fahrplan/v1/ teiid throws out again NPE
{code:noformat}
2017-12-20 16:29:10,238 WARN [org.teiid.RUNTIME] (Worker1_async-teiid-threads1) TEIID50036 VDB test.1 model "mswagger" metadata failed to load. Reason:java.lang.NullPointerExceptio
n: java.lang.NullPointerException
at org.teiid.metadata.MetadataFactory.setUUID(MetadataFactory.java:155)
at org.teiid.metadata.MetadataFactory.addProcedure(MetadataFactory.java:403)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.addProcedure(SwaggerMetadataProcessor.java:240)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.process(SwaggerMetadataProcessor.java:199)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.process(SwaggerMetadataProcessor.java:67)
at org.teiid.translator.ExecutionFactory.getMetadata(ExecutionFactory.java:961)
at org.teiid.query.metadata.NativeMetadataRepository.getMetadata(NativeMetadataRepository.java:96)
at org.teiid.query.metadata.NativeMetadataRepository.loadMetadata(NativeMetadataRepository.java:62)
at org.teiid.query.metadata.ChainingMetadataRepository.loadMetadata(ChainingMetadataRepository.java:55)
at org.teiid.jboss.VDBService$6.run(VDBService.java:341)
at org.teiid.jboss.VDBService$7.run(VDBService.java:392)
at org.teiid.dqp.internal.process.DQPWorkContext.runInContext(DQPWorkContext.java:284)
at org.teiid.dqp.internal.process.ThreadReuseExecutor$RunnableWrapper.run(ThreadReuseExecutor.java:119)
at org.teiid.dqp.internal.process.ThreadReuseExecutor$3.run(ThreadReuseExecutor.java:210)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
{code}
2. http://api.apis.guru/v2/specs/googleapis.com/doubleclicksearch/v2/ teiid throws out NPE but because of another circumstances:
{code:noformat}
2017-12-20 16:47:38,151 WARN [org.teiid.RUNTIME] (Worker1_async-teiid-threads1) TEIID50036 VDB test.1 model "mswagger" metadata failed to load. Reason:java.lang.NullPointerExceptio
n: java.lang.NullPointerException
at org.teiid.translator.swagger.SwaggerMetadataProcessor$3.execute(SwaggerMetadataProcessor.java:463)
at org.teiid.translator.swagger.SwaggerMetadataProcessor$2.visit(SwaggerMetadataProcessor.java:389)
at org.teiid.translator.swagger.PropertyVisitor.accept(PropertyVisitor.java:48)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.walkProperties(SwaggerMetadataProcessor.java:438)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.access$300(SwaggerMetadataProcessor.java:67)
at org.teiid.translator.swagger.SwaggerMetadataProcessor$2.visit(SwaggerMetadataProcessor.java:395)
at org.teiid.translator.swagger.PropertyVisitor.accept(PropertyVisitor.java:48)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.walkProperties(SwaggerMetadataProcessor.java:438)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.addProcedureParameters(SwaggerMetadataProcessor.java:482)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.addProcedure(SwaggerMetadataProcessor.java:254)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.process(SwaggerMetadataProcessor.java:199)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.process(SwaggerMetadataProcessor.java:67)
at org.teiid.translator.ExecutionFactory.getMetadata(ExecutionFactory.java:961)
at org.teiid.query.metadata.NativeMetadataRepository.getMetadata(NativeMetadataRepository.java:96)
at org.teiid.query.metadata.NativeMetadataRepository.loadMetadata(NativeMetadataRepository.java:62)
at org.teiid.query.metadata.ChainingMetadataRepository.loadMetadata(ChainingMetadataRepository.java:55)
at org.teiid.jboss.VDBService$6.run(VDBService.java:341)
at org.teiid.jboss.VDBService$7.run(VDBService.java:392)
at org.teiid.dqp.internal.process.DQPWorkContext.runInContext(DQPWorkContext.java:284)
at org.teiid.dqp.internal.process.ThreadReuseExecutor$RunnableWrapper.run(ThreadReuseExecutor.java:119)
at org.teiid.dqp.internal.process.ThreadReuseExecutor$3.run(ThreadReuseExecutor.java:210)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
{code}
3. http://api.apis.guru/v2/specs/magento.com/2.1/ teiid throws out StackOverflowError, there is a cycle:
{code:noformat}
2017-12-20 16:51:03,475 ERROR [org.teiid.RUNTIME] (Worker1) TEIID30021 Uncaught exception processing work: java.lang.StackOverflowError
at org.teiid.metadata.ColumnSet.getColumnByName(ColumnSet.java:59)
at org.teiid.metadata.MetadataFactory.addColumn(MetadataFactory.java:197)
at org.teiid.metadata.MetadataFactory.addProcedureResultSetColumn(MetadataFactory.java:453)
at org.teiid.translator.swagger.SwaggerMetadataProcessor$1.execute(SwaggerMetadataProcessor.java:286)
at org.teiid.translator.swagger.SwaggerMetadataProcessor$2.visit(SwaggerMetadataProcessor.java:383)
at org.teiid.translator.swagger.PropertyVisitor.accept(PropertyVisitor.java:58)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.walkProperties(SwaggerMetadataProcessor.java:438)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.access$300(SwaggerMetadataProcessor.java:67)
at org.teiid.translator.swagger.SwaggerMetadataProcessor$2.visit(SwaggerMetadataProcessor.java:403)
at org.teiid.translator.swagger.PropertyVisitor.accept(PropertyVisitor.java:48)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.walkProperties(SwaggerMetadataProcessor.java:438)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.access$300(SwaggerMetadataProcessor.java:67)
at org.teiid.translator.swagger.SwaggerMetadataProcessor$2.visit(SwaggerMetadataProcessor.java:403)
at org.teiid.translator.swagger.PropertyVisitor.accept(PropertyVisitor.java:48)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.walkProperties(SwaggerMetadataProcessor.java:438)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.access$300(SwaggerMetadataProcessor.java:67)
at org.teiid.translator.swagger.SwaggerMetadataProcessor$2.visit(SwaggerMetadataProcessor.java:403)
at org.teiid.translator.swagger.PropertyVisitor.accept(PropertyVisitor.java:48)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.walkProperties(SwaggerMetadataProcessor.java:438)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.access$300(SwaggerMetadataProcessor.java:67)
at org.teiid.translator.swagger.SwaggerMetadataProcessor$2.visit(SwaggerMetadataProcessor.java:403)
at org.teiid.translator.swagger.PropertyVisitor.accept(PropertyVisitor.java:48)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.walkProperties(SwaggerMetadataProcessor.java:438)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.access$300(SwaggerMetadataProcessor.java:67)
at org.teiid.translator.swagger.SwaggerMetadataProcessor$2.visit(SwaggerMetadataProcessor.java:403)
at org.teiid.translator.swagger.PropertyVisitor.accept(PropertyVisitor.java:48)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.walkProperties(SwaggerMetadataProcessor.java:438)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.access$300(SwaggerMetadataProcessor.java:67)
at org.teiid.translator.swagger.SwaggerMetadataProcessor$2.visit(SwaggerMetadataProcessor.java:403)
at org.teiid.translator.swagger.PropertyVisitor.accept(PropertyVisitor.java:48)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.walkProperties(SwaggerMetadataProcessor.java:438)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.access$300(SwaggerMetadataProcessor.java:67)
at org.teiid.translator.swagger.SwaggerMetadataProcessor$2.visit(SwaggerMetadataProcessor.java:403)
at org.teiid.translator.swagger.PropertyVisitor.accept(PropertyVisitor.java:48)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.walkProperties(SwaggerMetadataProcessor.java:438)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.access$300(SwaggerMetadataProcessor.java:67)
at org.teiid.translator.swagger.SwaggerMetadataProcessor$2.visit(SwaggerMetadataProcessor.java:403)
at org.teiid.translator.swagger.PropertyVisitor.accept(PropertyVisitor.java:48)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.walkProperties(SwaggerMetadataProcessor.java:438)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.access$300(SwaggerMetadataProcessor.java:67)
at org.teiid.translator.swagger.SwaggerMetadataProcessor$2.visit(SwaggerMetadataProcessor.java:403)
at org.teiid.translator.swagger.PropertyVisitor.accept(PropertyVisitor.java:48)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.walkProperties(SwaggerMetadataProcessor.java:438)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.access$300(SwaggerMetadataProcessor.java:67)
at org.teiid.translator.swagger.SwaggerMetadataProcessor$2.visit(SwaggerMetadataProcessor.java:403)
at org.teiid.translator.swagger.PropertyVisitor.accept(PropertyVisitor.java:48)
{code}
Another thing, teiid at the moment uses the following swagger versions according to the root pom.xml:
<version.swagger-parser>1.0.10</version.swagger-parser>
<version.io.swagger>1.5.8</version.io.swagger>
but these libraries are being actively changed. The latest stable versions for io.swagger is 1.5.17 and for swagger-parser is 1.0.33. Can be these versions updated as well?
> NPE in Swagger translator
> -------------------------
>
> Key: TEIID-5183
> URL: https://issues.jboss.org/browse/TEIID-5183
> Project: Teiid
> Issue Type: Bug
> Components: Misc. Connectors
> Affects Versions: 9.3.4
> Environment: teiid-9.3.4 on WildFly Full 10.0.0.Final (WildFly Core 2.0.10.Final)
> Reporter: dalex dalex
> Assignee: Steven Hawkins
> Fix For: 10.1, 9.3.6, 10.0.2
>
>
> When using the http://api.apis.guru/v2/specs/azure.com/redis/2017-10-01/ link as an endpoint for swagger resource adapter Teiid throws up the following error message (in bootstrapping phase), though with http://petstore.swagger.io/v2 endpoint according to the https://teiid.gitbooks.io/documents/reference/Swagger_Translator.html documentation the translator works:
> {code:noformat}
> 2017-12-18 16:14:43,975 WARN [org.teiid.RUNTIME] (Worker1_async-teiid-threads1) TEIID50036 VDB test.1 model "mswagger" metadata failed to load. Reason:java.lang.NullPointerExceptio
> n: java.lang.NullPointerException
> at org.teiid.metadata.MetadataFactory.setUUID(MetadataFactory.java:155)
> at org.teiid.metadata.MetadataFactory.addProcedureParameter(MetadataFactory.java:421)
> at org.teiid.translator.swagger.SwaggerMetadataProcessor.addProcedureParameters(SwaggerMetadataProcessor.java:560)
> at org.teiid.translator.swagger.SwaggerMetadataProcessor.addProcedure(SwaggerMetadataProcessor.java:261)
> at org.teiid.translator.swagger.SwaggerMetadataProcessor.process(SwaggerMetadataProcessor.java:206)
> at org.teiid.translator.swagger.SwaggerMetadataProcessor.process(SwaggerMetadataProcessor.java:74)
> at org.teiid.translator.ExecutionFactory.getMetadata(ExecutionFactory.java:961)
> at org.teiid.query.metadata.NativeMetadataRepository.getMetadata(NativeMetadataRepository.java:96)
> at org.teiid.query.metadata.NativeMetadataRepository.loadMetadata(NativeMetadataRepository.java:62)
> at org.teiid.query.metadata.ChainingMetadataRepository.loadMetadata(ChainingMetadataRepository.java:55)
> at org.teiid.jboss.VDBService$6.run(VDBService.java:341)
> at org.teiid.jboss.VDBService$7.run(VDBService.java:392)
> at org.teiid.dqp.internal.process.DQPWorkContext.runInContext(DQPWorkContext.java:284)
> at org.teiid.dqp.internal.process.ThreadReuseExecutor$RunnableWrapper.run(ThreadReuseExecutor.java:119)
> at org.teiid.dqp.internal.process.ThreadReuseExecutor$3.run(ThreadReuseExecutor.java:210)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
> at java.lang.Thread.run(Thread.java:745)
> {code}
> The http://api.apis.guru/v2/specs/azure.com/redis/2017-10-01/ endpoint supports swagger API according to the https://apis.guru/browse-apis/ link and I can see json output when requesting the http://api.apis.guru/v2/specs/azure.com/redis/2017-10-01/swagger.json link. Probably the NPE appears because of RefParameter type which is not handled in SwaggerMetadataProcessor.addProcedureParameters method which leads to name = null.
--
This message was sent by Atlassian JIRA
(v7.5.0#75005)
6 years, 4 months
- 1
- 0
[JBoss JIRA] (TEIID-5183) NPE in Swagger translator
by dalex dalex (JIRA)
[ https://issues.jboss.org/browse/TEIID-5183?page=com.atlassian.jira.plugin... ]
dalex dalex commented on TEIID-5183:
------------------------------------
Hi [~shawkins] thx a lot for the quick fix but it works for http://api.apis.guru/v2/specs/azure.com/redis/2017-10-01/ endpoint but doesn't work for the following ones (I applied all changes from the issue):
http://api.apis.guru/v2/specs/deutschebahn.com/fahrplan/v1/
http://api.apis.guru/v2/specs/googleapis.com/doubleclicksearch/v2/
http://api.apis.guru/v2/specs/magento.com/2.1/
let me demonstrate you stacktraces here for every endpoint:
1. http://api.apis.guru/v2/specs/deutschebahn.com/fahrplan/v1/ teiid throws out again NPE
{code:noformat}
2017-12-20 16:29:10,238 WARN [org.teiid.RUNTIME] (Worker1_async-teiid-threads1) TEIID50036 VDB test.1 model "mswagger" metadata failed to load. Reason:java.lang.NullPointerExceptio
n: java.lang.NullPointerException
at org.teiid.metadata.MetadataFactory.setUUID(MetadataFactory.java:155)
at org.teiid.metadata.MetadataFactory.addProcedure(MetadataFactory.java:403)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.addProcedure(SwaggerMetadataProcessor.java:240)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.process(SwaggerMetadataProcessor.java:199)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.process(SwaggerMetadataProcessor.java:67)
at org.teiid.translator.ExecutionFactory.getMetadata(ExecutionFactory.java:961)
at org.teiid.query.metadata.NativeMetadataRepository.getMetadata(NativeMetadataRepository.java:96)
at org.teiid.query.metadata.NativeMetadataRepository.loadMetadata(NativeMetadataRepository.java:62)
at org.teiid.query.metadata.ChainingMetadataRepository.loadMetadata(ChainingMetadataRepository.java:55)
at org.teiid.jboss.VDBService$6.run(VDBService.java:341)
at org.teiid.jboss.VDBService$7.run(VDBService.java:392)
at org.teiid.dqp.internal.process.DQPWorkContext.runInContext(DQPWorkContext.java:284)
at org.teiid.dqp.internal.process.ThreadReuseExecutor$RunnableWrapper.run(ThreadReuseExecutor.java:119)
at org.teiid.dqp.internal.process.ThreadReuseExecutor$3.run(ThreadReuseExecutor.java:210)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
{code}
2. http://api.apis.guru/v2/specs/googleapis.com/doubleclicksearch/v2/ teiid throws out NPE but because of another circumstances:
{code:noformat}
2017-12-20 16:47:38,151 WARN [org.teiid.RUNTIME] (Worker1_async-teiid-threads1) TEIID50036 VDB test.1 model "mswagger" metadata failed to load. Reason:java.lang.NullPointerExceptio
n: java.lang.NullPointerException
at org.teiid.translator.swagger.SwaggerMetadataProcessor$3.execute(SwaggerMetadataProcessor.java:463)
at org.teiid.translator.swagger.SwaggerMetadataProcessor$2.visit(SwaggerMetadataProcessor.java:389)
at org.teiid.translator.swagger.PropertyVisitor.accept(PropertyVisitor.java:48)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.walkProperties(SwaggerMetadataProcessor.java:438)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.access$300(SwaggerMetadataProcessor.java:67)
at org.teiid.translator.swagger.SwaggerMetadataProcessor$2.visit(SwaggerMetadataProcessor.java:395)
at org.teiid.translator.swagger.PropertyVisitor.accept(PropertyVisitor.java:48)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.walkProperties(SwaggerMetadataProcessor.java:438)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.addProcedureParameters(SwaggerMetadataProcessor.java:482)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.addProcedure(SwaggerMetadataProcessor.java:254)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.process(SwaggerMetadataProcessor.java:199)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.process(SwaggerMetadataProcessor.java:67)
at org.teiid.translator.ExecutionFactory.getMetadata(ExecutionFactory.java:961)
at org.teiid.query.metadata.NativeMetadataRepository.getMetadata(NativeMetadataRepository.java:96)
at org.teiid.query.metadata.NativeMetadataRepository.loadMetadata(NativeMetadataRepository.java:62)
at org.teiid.query.metadata.ChainingMetadataRepository.loadMetadata(ChainingMetadataRepository.java:55)
at org.teiid.jboss.VDBService$6.run(VDBService.java:341)
at org.teiid.jboss.VDBService$7.run(VDBService.java:392)
at org.teiid.dqp.internal.process.DQPWorkContext.runInContext(DQPWorkContext.java:284)
at org.teiid.dqp.internal.process.ThreadReuseExecutor$RunnableWrapper.run(ThreadReuseExecutor.java:119)
at org.teiid.dqp.internal.process.ThreadReuseExecutor$3.run(ThreadReuseExecutor.java:210)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
{code}
3. http://api.apis.guru/v2/specs/magento.com/2.1/ teiid throws out StackOverflowError, there is a cycle:
{code:noformat}
2017-12-20 16:51:03,475 ERROR [org.teiid.RUNTIME] (Worker1) TEIID30021 Uncaught exception processing work: java.lang.StackOverflowError
at org.teiid.metadata.ColumnSet.getColumnByName(ColumnSet.java:59)
at org.teiid.metadata.MetadataFactory.addColumn(MetadataFactory.java:197)
at org.teiid.metadata.MetadataFactory.addProcedureResultSetColumn(MetadataFactory.java:453)
at org.teiid.translator.swagger.SwaggerMetadataProcessor$1.execute(SwaggerMetadataProcessor.java:286)
at org.teiid.translator.swagger.SwaggerMetadataProcessor$2.visit(SwaggerMetadataProcessor.java:383)
at org.teiid.translator.swagger.PropertyVisitor.accept(PropertyVisitor.java:58)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.walkProperties(SwaggerMetadataProcessor.java:438)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.access$300(SwaggerMetadataProcessor.java:67)
at org.teiid.translator.swagger.SwaggerMetadataProcessor$2.visit(SwaggerMetadataProcessor.java:403)
at org.teiid.translator.swagger.PropertyVisitor.accept(PropertyVisitor.java:48)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.walkProperties(SwaggerMetadataProcessor.java:438)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.access$300(SwaggerMetadataProcessor.java:67)
at org.teiid.translator.swagger.SwaggerMetadataProcessor$2.visit(SwaggerMetadataProcessor.java:403)
at org.teiid.translator.swagger.PropertyVisitor.accept(PropertyVisitor.java:48)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.walkProperties(SwaggerMetadataProcessor.java:438)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.access$300(SwaggerMetadataProcessor.java:67)
at org.teiid.translator.swagger.SwaggerMetadataProcessor$2.visit(SwaggerMetadataProcessor.java:403)
at org.teiid.translator.swagger.PropertyVisitor.accept(PropertyVisitor.java:48)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.walkProperties(SwaggerMetadataProcessor.java:438)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.access$300(SwaggerMetadataProcessor.java:67)
at org.teiid.translator.swagger.SwaggerMetadataProcessor$2.visit(SwaggerMetadataProcessor.java:403)
at org.teiid.translator.swagger.PropertyVisitor.accept(PropertyVisitor.java:48)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.walkProperties(SwaggerMetadataProcessor.java:438)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.access$300(SwaggerMetadataProcessor.java:67)
at org.teiid.translator.swagger.SwaggerMetadataProcessor$2.visit(SwaggerMetadataProcessor.java:403)
at org.teiid.translator.swagger.PropertyVisitor.accept(PropertyVisitor.java:48)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.walkProperties(SwaggerMetadataProcessor.java:438)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.access$300(SwaggerMetadataProcessor.java:67)
at org.teiid.translator.swagger.SwaggerMetadataProcessor$2.visit(SwaggerMetadataProcessor.java:403)
at org.teiid.translator.swagger.PropertyVisitor.accept(PropertyVisitor.java:48)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.walkProperties(SwaggerMetadataProcessor.java:438)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.access$300(SwaggerMetadataProcessor.java:67)
at org.teiid.translator.swagger.SwaggerMetadataProcessor$2.visit(SwaggerMetadataProcessor.java:403)
at org.teiid.translator.swagger.PropertyVisitor.accept(PropertyVisitor.java:48)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.walkProperties(SwaggerMetadataProcessor.java:438)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.access$300(SwaggerMetadataProcessor.java:67)
at org.teiid.translator.swagger.SwaggerMetadataProcessor$2.visit(SwaggerMetadataProcessor.java:403)
at org.teiid.translator.swagger.PropertyVisitor.accept(PropertyVisitor.java:48)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.walkProperties(SwaggerMetadataProcessor.java:438)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.access$300(SwaggerMetadataProcessor.java:67)
at org.teiid.translator.swagger.SwaggerMetadataProcessor$2.visit(SwaggerMetadataProcessor.java:403)
at org.teiid.translator.swagger.PropertyVisitor.accept(PropertyVisitor.java:48)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.walkProperties(SwaggerMetadataProcessor.java:438)
at org.teiid.translator.swagger.SwaggerMetadataProcessor.access$300(SwaggerMetadataProcessor.java:67)
at org.teiid.translator.swagger.SwaggerMetadataProcessor$2.visit(SwaggerMetadataProcessor.java:403)
at org.teiid.translator.swagger.PropertyVisitor.accept(PropertyVisitor.java:48)
{code}
Another thing, teiid at the moment uses the following swagger versions according to the root pom.xml:
<version.swagger-parser>1.0.10</version.swagger-parser>
<version.io.swagger>1.5.8</version.io.swagger>
but these libraries are being actively changed. The latest stable versions for io.swagger is 1.5.17 and for swagger-parser is 1.0.33. Can be these versions updated as well?
> NPE in Swagger translator
> -------------------------
>
> Key: TEIID-5183
> URL: https://issues.jboss.org/browse/TEIID-5183
> Project: Teiid
> Issue Type: Bug
> Components: Misc. Connectors
> Affects Versions: 9.3.4
> Environment: teiid-9.3.4 on WildFly Full 10.0.0.Final (WildFly Core 2.0.10.Final)
> Reporter: dalex dalex
> Assignee: Steven Hawkins
> Fix For: 10.1, 9.3.6, 10.0.2
>
>
> When using the http://api.apis.guru/v2/specs/azure.com/redis/2017-10-01/ link as an endpoint for swagger resource adapter Teiid throws up the following error message (in bootstrapping phase), though with http://petstore.swagger.io/v2 endpoint according to the https://teiid.gitbooks.io/documents/reference/Swagger_Translator.html documentation the translator works:
> {code:noformat}
> 2017-12-18 16:14:43,975 WARN [org.teiid.RUNTIME] (Worker1_async-teiid-threads1) TEIID50036 VDB test.1 model "mswagger" metadata failed to load. Reason:java.lang.NullPointerExceptio
> n: java.lang.NullPointerException
> at org.teiid.metadata.MetadataFactory.setUUID(MetadataFactory.java:155)
> at org.teiid.metadata.MetadataFactory.addProcedureParameter(MetadataFactory.java:421)
> at org.teiid.translator.swagger.SwaggerMetadataProcessor.addProcedureParameters(SwaggerMetadataProcessor.java:560)
> at org.teiid.translator.swagger.SwaggerMetadataProcessor.addProcedure(SwaggerMetadataProcessor.java:261)
> at org.teiid.translator.swagger.SwaggerMetadataProcessor.process(SwaggerMetadataProcessor.java:206)
> at org.teiid.translator.swagger.SwaggerMetadataProcessor.process(SwaggerMetadataProcessor.java:74)
> at org.teiid.translator.ExecutionFactory.getMetadata(ExecutionFactory.java:961)
> at org.teiid.query.metadata.NativeMetadataRepository.getMetadata(NativeMetadataRepository.java:96)
> at org.teiid.query.metadata.NativeMetadataRepository.loadMetadata(NativeMetadataRepository.java:62)
> at org.teiid.query.metadata.ChainingMetadataRepository.loadMetadata(ChainingMetadataRepository.java:55)
> at org.teiid.jboss.VDBService$6.run(VDBService.java:341)
> at org.teiid.jboss.VDBService$7.run(VDBService.java:392)
> at org.teiid.dqp.internal.process.DQPWorkContext.runInContext(DQPWorkContext.java:284)
> at org.teiid.dqp.internal.process.ThreadReuseExecutor$RunnableWrapper.run(ThreadReuseExecutor.java:119)
> at org.teiid.dqp.internal.process.ThreadReuseExecutor$3.run(ThreadReuseExecutor.java:210)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
> at java.lang.Thread.run(Thread.java:745)
> {code}
> The http://api.apis.guru/v2/specs/azure.com/redis/2017-10-01/ endpoint supports swagger API according to the https://apis.guru/browse-apis/ link and I can see json output when requesting the http://api.apis.guru/v2/specs/azure.com/redis/2017-10-01/swagger.json link. Probably the NPE appears because of RefParameter type which is not handled in SwaggerMetadataProcessor.addProcedureParameters method which leads to name = null.
--
This message was sent by Atlassian JIRA
(v7.5.0#75005)
6 years, 4 months
- 1
- 0
[JBoss JIRA] (TEIID-5186) NPE in QueryResolver when calling virtual procedure
by dalex dalex (JIRA)
[ https://issues.jboss.org/browse/TEIID-5186?page=com.atlassian.jira.plugin... ]
dalex dalex updated TEIID-5186:
-------------------------------
Description:
When running query:
{code:sql}
select * from (call procs.pr0()) a
{code}
teiid is throwing out the following stacktrace:
{code:noformat}
2017-12-20 14:28:12,939 ERROR [org.teiid.PROCESSOR] (Worker2_QueryProcessorQueue6) hVe+gXzCsZCA TEIID30019 Unexpected exception for request hVe+gXzCsZCA.1: java.lang.NullPointerExcep
tion
at org.teiid.query.resolver.QueryResolver.resolveView(QueryResolver.java:387)
at org.teiid.query.optimizer.relational.RelationalPlanner.resolveVirtualGroup(RelationalPlanner.java:2080)
at org.teiid.query.optimizer.relational.RelationalPlanner.buildTree(RelationalPlanner.java:1462)
at org.teiid.query.optimizer.relational.RelationalPlanner.createQueryPlan(RelationalPlanner.java:1349)
at org.teiid.query.optimizer.relational.RelationalPlanner.createQueryPlan(RelationalPlanner.java:1300)
at org.teiid.query.optimizer.relational.RelationalPlanner.generatePlan(RelationalPlanner.java:1027)
at org.teiid.query.optimizer.relational.RelationalPlanner.optimize(RelationalPlanner.java:203)
at org.teiid.query.optimizer.QueryOptimizer.optimizePlan(QueryOptimizer.java:179)
at org.teiid.query.optimizer.relational.RelationalPlanner.planSubqueries(RelationalPlanner.java:737)
at org.teiid.query.optimizer.relational.RelationalPlanner.connectSubqueryContainers(RelationalPlanner.java:696)
at org.teiid.query.optimizer.relational.RelationalPlanner.optimize(RelationalPlanner.java:220)
at org.teiid.query.optimizer.QueryOptimizer.optimizePlan(QueryOptimizer.java:179)
at org.teiid.query.optimizer.ProcedurePlanner.optimize(ProcedurePlanner.java:86)
at org.teiid.query.optimizer.QueryOptimizer.planProcedure(QueryOptimizer.java:206)
at org.teiid.query.optimizer.QueryOptimizer.optimizePlan(QueryOptimizer.java:146)
at org.teiid.query.optimizer.relational.RelationalPlanner.addNestedCommand(RelationalPlanner.java:1719)
at org.teiid.query.optimizer.relational.RelationalPlanner.addNestedProcedure(RelationalPlanner.java:1181)
at org.teiid.query.optimizer.relational.RelationalPlanner.createStoredProcedurePlan(RelationalPlanner.java:1271)
at org.teiid.query.optimizer.relational.RelationalPlanner.generatePlan(RelationalPlanner.java:1037)
at org.teiid.query.optimizer.relational.RelationalPlanner.addNestedCommand(RelationalPlanner.java:1709)
at org.teiid.query.optimizer.relational.RelationalPlanner.buildTree(RelationalPlanner.java:1532)
at org.teiid.query.optimizer.relational.RelationalPlanner.createQueryPlan(RelationalPlanner.java:1349)
at org.teiid.query.optimizer.relational.RelationalPlanner.createQueryPlan(RelationalPlanner.java:1300)
at org.teiid.query.optimizer.relational.RelationalPlanner.generatePlan(RelationalPlanner.java:1027)
at org.teiid.query.optimizer.relational.RelationalPlanner.optimize(RelationalPlanner.java:203)
at org.teiid.query.optimizer.QueryOptimizer.optimizePlan(QueryOptimizer.java:179)
at org.teiid.dqp.internal.process.Request.generatePlan(Request.java:458)
at org.teiid.dqp.internal.process.Request.processRequest(Request.java:486)
at org.teiid.dqp.internal.process.RequestWorkItem.processNew(RequestWorkItem.java:660)
at org.teiid.dqp.internal.process.RequestWorkItem.process(RequestWorkItem.java:339)
at org.teiid.dqp.internal.process.AbstractWorkItem.run(AbstractWorkItem.java:47)
at org.teiid.dqp.internal.process.RequestWorkItem.run(RequestWorkItem.java:276)
at org.teiid.dqp.internal.process.DQPWorkContext.runInContext(DQPWorkContext.java:280)
at org.teiid.dqp.internal.process.ThreadReuseExecutor$RunnableWrapper.run(ThreadReuseExecutor.java:115)
at org.teiid.dqp.internal.process.ThreadReuseExecutor$3.run(ThreadReuseExecutor.java:206)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
{code}
was:
When running query:
{code:sql}
select * from (call procs.pr0()) a
{code}
teiid throwing out the following stacktrace:
{code:noformat}
2017-12-20 14:28:12,939 ERROR [org.teiid.PROCESSOR] (Worker2_QueryProcessorQueue6) hVe+gXzCsZCA TEIID30019 Unexpected exception for request hVe+gXzCsZCA.1: java.lang.NullPointerExcep
tion
at org.teiid.query.resolver.QueryResolver.resolveView(QueryResolver.java:387)
at org.teiid.query.optimizer.relational.RelationalPlanner.resolveVirtualGroup(RelationalPlanner.java:2080)
at org.teiid.query.optimizer.relational.RelationalPlanner.buildTree(RelationalPlanner.java:1462)
at org.teiid.query.optimizer.relational.RelationalPlanner.createQueryPlan(RelationalPlanner.java:1349)
at org.teiid.query.optimizer.relational.RelationalPlanner.createQueryPlan(RelationalPlanner.java:1300)
at org.teiid.query.optimizer.relational.RelationalPlanner.generatePlan(RelationalPlanner.java:1027)
at org.teiid.query.optimizer.relational.RelationalPlanner.optimize(RelationalPlanner.java:203)
at org.teiid.query.optimizer.QueryOptimizer.optimizePlan(QueryOptimizer.java:179)
at org.teiid.query.optimizer.relational.RelationalPlanner.planSubqueries(RelationalPlanner.java:737)
at org.teiid.query.optimizer.relational.RelationalPlanner.connectSubqueryContainers(RelationalPlanner.java:696)
at org.teiid.query.optimizer.relational.RelationalPlanner.optimize(RelationalPlanner.java:220)
at org.teiid.query.optimizer.QueryOptimizer.optimizePlan(QueryOptimizer.java:179)
at org.teiid.query.optimizer.ProcedurePlanner.optimize(ProcedurePlanner.java:86)
at org.teiid.query.optimizer.QueryOptimizer.planProcedure(QueryOptimizer.java:206)
at org.teiid.query.optimizer.QueryOptimizer.optimizePlan(QueryOptimizer.java:146)
at org.teiid.query.optimizer.relational.RelationalPlanner.addNestedCommand(RelationalPlanner.java:1719)
at org.teiid.query.optimizer.relational.RelationalPlanner.addNestedProcedure(RelationalPlanner.java:1181)
at org.teiid.query.optimizer.relational.RelationalPlanner.createStoredProcedurePlan(RelationalPlanner.java:1271)
at org.teiid.query.optimizer.relational.RelationalPlanner.generatePlan(RelationalPlanner.java:1037)
at org.teiid.query.optimizer.relational.RelationalPlanner.addNestedCommand(RelationalPlanner.java:1709)
at org.teiid.query.optimizer.relational.RelationalPlanner.buildTree(RelationalPlanner.java:1532)
at org.teiid.query.optimizer.relational.RelationalPlanner.createQueryPlan(RelationalPlanner.java:1349)
at org.teiid.query.optimizer.relational.RelationalPlanner.createQueryPlan(RelationalPlanner.java:1300)
at org.teiid.query.optimizer.relational.RelationalPlanner.generatePlan(RelationalPlanner.java:1027)
at org.teiid.query.optimizer.relational.RelationalPlanner.optimize(RelationalPlanner.java:203)
at org.teiid.query.optimizer.QueryOptimizer.optimizePlan(QueryOptimizer.java:179)
at org.teiid.dqp.internal.process.Request.generatePlan(Request.java:458)
at org.teiid.dqp.internal.process.Request.processRequest(Request.java:486)
at org.teiid.dqp.internal.process.RequestWorkItem.processNew(RequestWorkItem.java:660)
at org.teiid.dqp.internal.process.RequestWorkItem.process(RequestWorkItem.java:339)
at org.teiid.dqp.internal.process.AbstractWorkItem.run(AbstractWorkItem.java:47)
at org.teiid.dqp.internal.process.RequestWorkItem.run(RequestWorkItem.java:276)
at org.teiid.dqp.internal.process.DQPWorkContext.runInContext(DQPWorkContext.java:280)
at org.teiid.dqp.internal.process.ThreadReuseExecutor$RunnableWrapper.run(ThreadReuseExecutor.java:115)
at org.teiid.dqp.internal.process.ThreadReuseExecutor$3.run(ThreadReuseExecutor.java:206)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
{code}
> NPE in QueryResolver when calling virtual procedure
> ---------------------------------------------------
>
> Key: TEIID-5186
> URL: https://issues.jboss.org/browse/TEIID-5186
> Project: Teiid
> Issue Type: Bug
> Components: Query Engine
> Affects Versions: 10.0.1
> Environment: teiid-10.0.1 on WildFly Full 11.0.0.Final (WildFly Core 3.0.8.Final)
> Reporter: dalex dalex
> Assignee: Steven Hawkins
> Priority: Blocker
>
> When running query:
> {code:sql}
> select * from (call procs.pr0()) a
> {code}
> teiid is throwing out the following stacktrace:
> {code:noformat}
> 2017-12-20 14:28:12,939 ERROR [org.teiid.PROCESSOR] (Worker2_QueryProcessorQueue6) hVe+gXzCsZCA TEIID30019 Unexpected exception for request hVe+gXzCsZCA.1: java.lang.NullPointerExcep
> tion
> at org.teiid.query.resolver.QueryResolver.resolveView(QueryResolver.java:387)
> at org.teiid.query.optimizer.relational.RelationalPlanner.resolveVirtualGroup(RelationalPlanner.java:2080)
> at org.teiid.query.optimizer.relational.RelationalPlanner.buildTree(RelationalPlanner.java:1462)
> at org.teiid.query.optimizer.relational.RelationalPlanner.createQueryPlan(RelationalPlanner.java:1349)
> at org.teiid.query.optimizer.relational.RelationalPlanner.createQueryPlan(RelationalPlanner.java:1300)
> at org.teiid.query.optimizer.relational.RelationalPlanner.generatePlan(RelationalPlanner.java:1027)
> at org.teiid.query.optimizer.relational.RelationalPlanner.optimize(RelationalPlanner.java:203)
> at org.teiid.query.optimizer.QueryOptimizer.optimizePlan(QueryOptimizer.java:179)
> at org.teiid.query.optimizer.relational.RelationalPlanner.planSubqueries(RelationalPlanner.java:737)
> at org.teiid.query.optimizer.relational.RelationalPlanner.connectSubqueryContainers(RelationalPlanner.java:696)
> at org.teiid.query.optimizer.relational.RelationalPlanner.optimize(RelationalPlanner.java:220)
> at org.teiid.query.optimizer.QueryOptimizer.optimizePlan(QueryOptimizer.java:179)
> at org.teiid.query.optimizer.ProcedurePlanner.optimize(ProcedurePlanner.java:86)
> at org.teiid.query.optimizer.QueryOptimizer.planProcedure(QueryOptimizer.java:206)
> at org.teiid.query.optimizer.QueryOptimizer.optimizePlan(QueryOptimizer.java:146)
> at org.teiid.query.optimizer.relational.RelationalPlanner.addNestedCommand(RelationalPlanner.java:1719)
> at org.teiid.query.optimizer.relational.RelationalPlanner.addNestedProcedure(RelationalPlanner.java:1181)
> at org.teiid.query.optimizer.relational.RelationalPlanner.createStoredProcedurePlan(RelationalPlanner.java:1271)
> at org.teiid.query.optimizer.relational.RelationalPlanner.generatePlan(RelationalPlanner.java:1037)
> at org.teiid.query.optimizer.relational.RelationalPlanner.addNestedCommand(RelationalPlanner.java:1709)
> at org.teiid.query.optimizer.relational.RelationalPlanner.buildTree(RelationalPlanner.java:1532)
> at org.teiid.query.optimizer.relational.RelationalPlanner.createQueryPlan(RelationalPlanner.java:1349)
> at org.teiid.query.optimizer.relational.RelationalPlanner.createQueryPlan(RelationalPlanner.java:1300)
> at org.teiid.query.optimizer.relational.RelationalPlanner.generatePlan(RelationalPlanner.java:1027)
> at org.teiid.query.optimizer.relational.RelationalPlanner.optimize(RelationalPlanner.java:203)
> at org.teiid.query.optimizer.QueryOptimizer.optimizePlan(QueryOptimizer.java:179)
> at org.teiid.dqp.internal.process.Request.generatePlan(Request.java:458)
> at org.teiid.dqp.internal.process.Request.processRequest(Request.java:486)
> at org.teiid.dqp.internal.process.RequestWorkItem.processNew(RequestWorkItem.java:660)
> at org.teiid.dqp.internal.process.RequestWorkItem.process(RequestWorkItem.java:339)
> at org.teiid.dqp.internal.process.AbstractWorkItem.run(AbstractWorkItem.java:47)
> at org.teiid.dqp.internal.process.RequestWorkItem.run(RequestWorkItem.java:276)
> at org.teiid.dqp.internal.process.DQPWorkContext.runInContext(DQPWorkContext.java:280)
> at org.teiid.dqp.internal.process.ThreadReuseExecutor$RunnableWrapper.run(ThreadReuseExecutor.java:115)
> at org.teiid.dqp.internal.process.ThreadReuseExecutor$3.run(ThreadReuseExecutor.java:206)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
> at java.lang.Thread.run(Thread.java:745)
> {code}
--
This message was sent by Atlassian JIRA
(v7.5.0#75005)
6 years, 4 months
- 1
- 0
[JBoss JIRA] (TEIID-5186) NPE in QueryResolver when calling virtual procedure
by dalex dalex (JIRA)
dalex dalex created TEIID-5186:
----------------------------------
Summary: NPE in QueryResolver when calling virtual procedure
Key: TEIID-5186
URL: https://issues.jboss.org/browse/TEIID-5186
Project: Teiid
Issue Type: Bug
Components: Query Engine
Affects Versions: 10.0.1
Environment: teiid-10.0.1 on WildFly Full 11.0.0.Final (WildFly Core 3.0.8.Final)
Reporter: dalex dalex
Assignee: Steven Hawkins
Priority: Blocker
When running query:
{code:sql}
select * from (call procs.pr0()) a
{code}
teiid throwing out the following stacktrace:
{code:noformat}
2017-12-20 14:28:12,939 ERROR [org.teiid.PROCESSOR] (Worker2_QueryProcessorQueue6) hVe+gXzCsZCA TEIID30019 Unexpected exception for request hVe+gXzCsZCA.1: java.lang.NullPointerExcep
tion
at org.teiid.query.resolver.QueryResolver.resolveView(QueryResolver.java:387)
at org.teiid.query.optimizer.relational.RelationalPlanner.resolveVirtualGroup(RelationalPlanner.java:2080)
at org.teiid.query.optimizer.relational.RelationalPlanner.buildTree(RelationalPlanner.java:1462)
at org.teiid.query.optimizer.relational.RelationalPlanner.createQueryPlan(RelationalPlanner.java:1349)
at org.teiid.query.optimizer.relational.RelationalPlanner.createQueryPlan(RelationalPlanner.java:1300)
at org.teiid.query.optimizer.relational.RelationalPlanner.generatePlan(RelationalPlanner.java:1027)
at org.teiid.query.optimizer.relational.RelationalPlanner.optimize(RelationalPlanner.java:203)
at org.teiid.query.optimizer.QueryOptimizer.optimizePlan(QueryOptimizer.java:179)
at org.teiid.query.optimizer.relational.RelationalPlanner.planSubqueries(RelationalPlanner.java:737)
at org.teiid.query.optimizer.relational.RelationalPlanner.connectSubqueryContainers(RelationalPlanner.java:696)
at org.teiid.query.optimizer.relational.RelationalPlanner.optimize(RelationalPlanner.java:220)
at org.teiid.query.optimizer.QueryOptimizer.optimizePlan(QueryOptimizer.java:179)
at org.teiid.query.optimizer.ProcedurePlanner.optimize(ProcedurePlanner.java:86)
at org.teiid.query.optimizer.QueryOptimizer.planProcedure(QueryOptimizer.java:206)
at org.teiid.query.optimizer.QueryOptimizer.optimizePlan(QueryOptimizer.java:146)
at org.teiid.query.optimizer.relational.RelationalPlanner.addNestedCommand(RelationalPlanner.java:1719)
at org.teiid.query.optimizer.relational.RelationalPlanner.addNestedProcedure(RelationalPlanner.java:1181)
at org.teiid.query.optimizer.relational.RelationalPlanner.createStoredProcedurePlan(RelationalPlanner.java:1271)
at org.teiid.query.optimizer.relational.RelationalPlanner.generatePlan(RelationalPlanner.java:1037)
at org.teiid.query.optimizer.relational.RelationalPlanner.addNestedCommand(RelationalPlanner.java:1709)
at org.teiid.query.optimizer.relational.RelationalPlanner.buildTree(RelationalPlanner.java:1532)
at org.teiid.query.optimizer.relational.RelationalPlanner.createQueryPlan(RelationalPlanner.java:1349)
at org.teiid.query.optimizer.relational.RelationalPlanner.createQueryPlan(RelationalPlanner.java:1300)
at org.teiid.query.optimizer.relational.RelationalPlanner.generatePlan(RelationalPlanner.java:1027)
at org.teiid.query.optimizer.relational.RelationalPlanner.optimize(RelationalPlanner.java:203)
at org.teiid.query.optimizer.QueryOptimizer.optimizePlan(QueryOptimizer.java:179)
at org.teiid.dqp.internal.process.Request.generatePlan(Request.java:458)
at org.teiid.dqp.internal.process.Request.processRequest(Request.java:486)
at org.teiid.dqp.internal.process.RequestWorkItem.processNew(RequestWorkItem.java:660)
at org.teiid.dqp.internal.process.RequestWorkItem.process(RequestWorkItem.java:339)
at org.teiid.dqp.internal.process.AbstractWorkItem.run(AbstractWorkItem.java:47)
at org.teiid.dqp.internal.process.RequestWorkItem.run(RequestWorkItem.java:276)
at org.teiid.dqp.internal.process.DQPWorkContext.runInContext(DQPWorkContext.java:280)
at org.teiid.dqp.internal.process.ThreadReuseExecutor$RunnableWrapper.run(ThreadReuseExecutor.java:115)
at org.teiid.dqp.internal.process.ThreadReuseExecutor$3.run(ThreadReuseExecutor.java:206)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
{code}
--
This message was sent by Atlassian JIRA
(v7.5.0#75005)
6 years, 4 months
- 1
- 0
[JBoss JIRA] (TEIID-5186) NPE in QueryResolver when calling virtual procedure
by dalex dalex (JIRA)
[ https://issues.jboss.org/browse/TEIID-5186?page=com.atlassian.jira.plugin... ]
dalex dalex updated TEIID-5186:
-------------------------------
Steps to Reproduce:
1. create the following view and proc:
{code:xml}
<model visible = "true" type = "VIRTUAL" name = "views">
<metadata type = "DDL"><![CDATA[
create view v as select 1 as a1
]]>
</metadata>
</model>
<model visible = "true" type = "VIRTUAL" name = "procs">
<metadata type = "DDL"><![CDATA[
create virtual procedure pr0() returns (res integer) as
begin
select a.a1 from (SELECT * FROM views.v p) a where a.a1 in (select a1 from a);
end
]]>
</metadata>
</model>
{code}
2. run the query:
{code:sql}
select * from (call procs.pr0()) a
{code}
but changing pr0 procedure on (changing sub-query in "in" clause):
{code:xml}
<model visible = "true" type = "VIRTUAL" name = "procs">
<metadata type = "DDL"><![CDATA[
create virtual procedure pr0() returns (res integer) as
begin
select a.a1 from (SELECT * FROM views.v p) a where a.a1 in (1);
end
]]>
</metadata>
</model>
{code}
solves the NPE.
was:
1. create the following view and procs:
{code:xml}
<model visible = "true" type = "VIRTUAL" name = "views">
<metadata type = "DDL"><![CDATA[
create view v as select 1 as a1
]]>
</metadata>
</model>
<model visible = "true" type = "VIRTUAL" name = "procs">
<metadata type = "DDL"><![CDATA[
create virtual procedure pr0() returns (res integer) as
begin
select a.a1 from (SELECT * FROM views.v p) a where a.a1 in (select a1 from a);
end
]]>
</metadata>
</model>
{code}
2. run the query:
{code:sql}
select * from (call procs.pr0()) a
{code}
but changing pr0 procedure on (changing sub-query in "in" clause):
{code:xml}
<model visible = "true" type = "VIRTUAL" name = "procs">
<metadata type = "DDL"><![CDATA[
create virtual procedure pr0() returns (res integer) as
begin
select a.a1 from (SELECT * FROM views.v p) a where a.a1 in (1);
end
]]>
</metadata>
</model>
{code}
solves the NPE.
> NPE in QueryResolver when calling virtual procedure
> ---------------------------------------------------
>
> Key: TEIID-5186
> URL: https://issues.jboss.org/browse/TEIID-5186
> Project: Teiid
> Issue Type: Bug
> Components: Query Engine
> Affects Versions: 10.0.1
> Environment: teiid-10.0.1 on WildFly Full 11.0.0.Final (WildFly Core 3.0.8.Final)
> Reporter: dalex dalex
> Assignee: Steven Hawkins
> Priority: Blocker
>
> When running query:
> {code:sql}
> select * from (call procs.pr0()) a
> {code}
> teiid throwing out the following stacktrace:
> {code:noformat}
> 2017-12-20 14:28:12,939 ERROR [org.teiid.PROCESSOR] (Worker2_QueryProcessorQueue6) hVe+gXzCsZCA TEIID30019 Unexpected exception for request hVe+gXzCsZCA.1: java.lang.NullPointerExcep
> tion
> at org.teiid.query.resolver.QueryResolver.resolveView(QueryResolver.java:387)
> at org.teiid.query.optimizer.relational.RelationalPlanner.resolveVirtualGroup(RelationalPlanner.java:2080)
> at org.teiid.query.optimizer.relational.RelationalPlanner.buildTree(RelationalPlanner.java:1462)
> at org.teiid.query.optimizer.relational.RelationalPlanner.createQueryPlan(RelationalPlanner.java:1349)
> at org.teiid.query.optimizer.relational.RelationalPlanner.createQueryPlan(RelationalPlanner.java:1300)
> at org.teiid.query.optimizer.relational.RelationalPlanner.generatePlan(RelationalPlanner.java:1027)
> at org.teiid.query.optimizer.relational.RelationalPlanner.optimize(RelationalPlanner.java:203)
> at org.teiid.query.optimizer.QueryOptimizer.optimizePlan(QueryOptimizer.java:179)
> at org.teiid.query.optimizer.relational.RelationalPlanner.planSubqueries(RelationalPlanner.java:737)
> at org.teiid.query.optimizer.relational.RelationalPlanner.connectSubqueryContainers(RelationalPlanner.java:696)
> at org.teiid.query.optimizer.relational.RelationalPlanner.optimize(RelationalPlanner.java:220)
> at org.teiid.query.optimizer.QueryOptimizer.optimizePlan(QueryOptimizer.java:179)
> at org.teiid.query.optimizer.ProcedurePlanner.optimize(ProcedurePlanner.java:86)
> at org.teiid.query.optimizer.QueryOptimizer.planProcedure(QueryOptimizer.java:206)
> at org.teiid.query.optimizer.QueryOptimizer.optimizePlan(QueryOptimizer.java:146)
> at org.teiid.query.optimizer.relational.RelationalPlanner.addNestedCommand(RelationalPlanner.java:1719)
> at org.teiid.query.optimizer.relational.RelationalPlanner.addNestedProcedure(RelationalPlanner.java:1181)
> at org.teiid.query.optimizer.relational.RelationalPlanner.createStoredProcedurePlan(RelationalPlanner.java:1271)
> at org.teiid.query.optimizer.relational.RelationalPlanner.generatePlan(RelationalPlanner.java:1037)
> at org.teiid.query.optimizer.relational.RelationalPlanner.addNestedCommand(RelationalPlanner.java:1709)
> at org.teiid.query.optimizer.relational.RelationalPlanner.buildTree(RelationalPlanner.java:1532)
> at org.teiid.query.optimizer.relational.RelationalPlanner.createQueryPlan(RelationalPlanner.java:1349)
> at org.teiid.query.optimizer.relational.RelationalPlanner.createQueryPlan(RelationalPlanner.java:1300)
> at org.teiid.query.optimizer.relational.RelationalPlanner.generatePlan(RelationalPlanner.java:1027)
> at org.teiid.query.optimizer.relational.RelationalPlanner.optimize(RelationalPlanner.java:203)
> at org.teiid.query.optimizer.QueryOptimizer.optimizePlan(QueryOptimizer.java:179)
> at org.teiid.dqp.internal.process.Request.generatePlan(Request.java:458)
> at org.teiid.dqp.internal.process.Request.processRequest(Request.java:486)
> at org.teiid.dqp.internal.process.RequestWorkItem.processNew(RequestWorkItem.java:660)
> at org.teiid.dqp.internal.process.RequestWorkItem.process(RequestWorkItem.java:339)
> at org.teiid.dqp.internal.process.AbstractWorkItem.run(AbstractWorkItem.java:47)
> at org.teiid.dqp.internal.process.RequestWorkItem.run(RequestWorkItem.java:276)
> at org.teiid.dqp.internal.process.DQPWorkContext.runInContext(DQPWorkContext.java:280)
> at org.teiid.dqp.internal.process.ThreadReuseExecutor$RunnableWrapper.run(ThreadReuseExecutor.java:115)
> at org.teiid.dqp.internal.process.ThreadReuseExecutor$3.run(ThreadReuseExecutor.java:206)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
> at java.lang.Thread.run(Thread.java:745)
> {code}
--
This message was sent by Atlassian JIRA
(v7.5.0#75005)
6 years, 4 months
- 1
- 0
[JBoss JIRA] (TEIID-5185) JDBC client intermittently hangs when processing multi-batch result sets from server
by Krum Bakalsky (JIRA)
[ https://issues.jboss.org/browse/TEIID-5185?page=com.atlassian.jira.plugin... ]
Krum Bakalsky updated TEIID-5185:
---------------------------------
Description:
We have a server-side application that is powered by Teiid version 9.3.4, and that exposes a Teiid JDBC endpoint to its clients.
A couple of app instances are configured to sit behind a VIP load balancer, that works on the TCP level.
We have been experiencing intermittently following problem, when we run Teiid 9.3.4 client to execute multi-batch queries to the server:
* client successfully fetches few batches from server;
* client hangs and its thread blocks on waiting for the next batch to be delivered on the network;
* after 1 hour client throws exceptions that Socket is closed.
When building up the JDBC connection URL the client refers directly to the server's VIP, and does not list particular server hosts:
jdbc:teiid:<Application>@mm://<VIP's DNS name>:<port>
Client thread's call stack:
{code}
"Thread Group 1-1" #41 prio=6 os_prio=0 tid=0x000000005e03a800 nid=0x17bc runnable [0x00000000623ae000]
java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.socketRead(Unknown Source)
at java.net.SocketInputStream.read(Unknown Source)
at java.net.SocketInputStream.read(Unknown Source)
at java.io.BufferedInputStream.fill(Unknown Source)
at java.io.BufferedInputStream.read(Unknown Source)
- locked <0x00000000f5f32420> (a org.teiid.core.util.AccessibleBufferedInputStream)
at java.io.DataInputStream.readInt(Unknown Source)
at org.teiid.netty.handler.codec.serialization.ObjectDecoderInputStream.readObjectOverride(ObjectDecoderInputStream.java:97)
at java.io.ObjectInputStream.readObject(Unknown Source)
at org.teiid.net.socket.OioOjbectChannelFactory$OioObjectChannel.read(OioOjbectChannelFactory.java:117)
at org.teiid.net.socket.SocketServerInstanceImpl.read(SocketServerInstanceImpl.java:324)
at sun.reflect.GeneratedMethodAccessor22.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
at java.lang.reflect.Method.invoke(Unknown Source)
at org.teiid.net.socket.SocketServerConnectionFactory$ShutdownHandler.invoke(SocketServerConnectionFactory.java:98)
at com.sun.proxy.$Proxy21.read(Unknown Source)
at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler$1.get(SocketServerInstanceImpl.java:427)
at org.teiid.jdbc.ResultSetImpl.getResults(ResultSetImpl.java:449)
at org.teiid.jdbc.ResultSetImpl.requestBatch(ResultSetImpl.java:382)
at org.teiid.jdbc.BatchResults.requestBatchAndWait(BatchResults.java:227)
at org.teiid.jdbc.BatchResults.requestNextBatch(BatchResults.java:142)
at org.teiid.jdbc.BatchResults.hasNext(BatchResults.java:253)
at org.teiid.jdbc.ResultSetImpl.hasNext(ResultSetImpl.java:510)
at org.teiid.jdbc.ResultSetImpl.next(ResultSetImpl.java:259)
at org.apache.commons.dbcp2.DelegatingResultSet.next(DelegatingResultSet.java:191)
at org.apache.commons.dbcp2.DelegatingResultSet.next(DelegatingResultSet.java:191)
at org.apache.jmeter.protocol.jdbc.AbstractJDBCTestElement.getStringFromResultSet(AbstractJDBCTestElement.java:535)
at org.apache.jmeter.protocol.jdbc.AbstractJDBCTestElement.execute(AbstractJDBCTestElement.java:174)
at org.apache.jmeter.protocol.jdbc.sampler.JDBCSampler.sample(JDBCSampler.java:84)
at org.apache.jmeter.threads.JMeterThread.executeSamplePackage(JMeterThread.java:491)
at org.apache.jmeter.threads.JMeterThread.processSampler(JMeterThread.java:425)
at org.apache.jmeter.threads.JMeterThread.run(JMeterThread.java:254)
at java.lang.Thread.run(Unknown Source)
Locked ownable synchronizers:
- None
{code}
Client side exception after 1 hour:
{code}
2017-12-19 13:17:07,160 WARN o.a.j.p.j.AbstractJDBCTestElement: Error closing ResultSet
org.teiid.jdbc.TeiidSQLException: TEIID20013 java.net.SocketException: Socket closed
at org.teiid.jdbc.TeiidSQLException.create(TeiidSQLException.java:135) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.jdbc.TeiidSQLException.create(TeiidSQLException.java:71) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:168) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.apache.commons.dbcp2.DelegatingResultSet.close(DelegatingResultSet.java:170) ~[commons-dbcp2-2.1.1.jar:2.1.1]
at org.apache.commons.dbcp2.DelegatingResultSet.close(DelegatingResultSet.java:170) ~[commons-dbcp2-2.1.1.jar:2.1.1]
at org.apache.jmeter.protocol.jdbc.AbstractJDBCTestElement.close(AbstractJDBCTestElement.java:607) [ApacheJMeter_jdbc.jar:3.2 r1790748]
at org.apache.jmeter.protocol.jdbc.AbstractJDBCTestElement.execute(AbstractJDBCTestElement.java:176) [ApacheJMeter_jdbc.jar:3.2 r1790748]
at org.apache.jmeter.protocol.jdbc.sampler.JDBCSampler.sample(JDBCSampler.java:84) [ApacheJMeter_jdbc.jar:3.2 r1790748]
at org.apache.jmeter.threads.JMeterThread.executeSamplePackage(JMeterThread.java:491) [ApacheJMeter_core.jar:3.2 r1790748]
at org.apache.jmeter.threads.JMeterThread.processSampler(JMeterThread.java:425) [ApacheJMeter_core.jar:3.2 r1790748]
at org.apache.jmeter.threads.JMeterThread.run(JMeterThread.java:254) [ApacheJMeter_core.jar:3.2 r1790748]
at java.lang.Thread.run(Unknown Source) [?:1.8.0_121]
Caused by: org.teiid.core.TeiidComponentException: TEIID20013 java.net.SocketException: Socket closed
at org.teiid.client.util.ExceptionUtil.convertException(ExceptionUtil.java:65) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler.invoke(SocketServerInstanceImpl.java:445) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.net.socket.SocketServerConnection$1.invoke(SocketServerConnection.java:293) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at com.sun.proxy.$Proxy24.closeRequest(Unknown Source) ~[?:?]
at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:164) ~[teiid-9.3.4-jdbc.jar:9.3.4]
... 9 more
Caused by: org.teiid.net.socket.SingleInstanceCommunicationException: TEIID20013 java.net.SocketException: Socket closed
at org.teiid.net.socket.SocketServerInstanceImpl.send(SocketServerInstanceImpl.java:217) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at sun.reflect.GeneratedMethodAccessor24.invoke(Unknown Source) ~[?:?]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[?:1.8.0_121]
at java.lang.reflect.Method.invoke(Unknown Source) ~[?:1.8.0_121]
at org.teiid.net.socket.SocketServerConnectionFactory$ShutdownHandler.invoke(SocketServerConnectionFactory.java:98) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at com.sun.proxy.$Proxy21.send(Unknown Source) ~[?:?]
at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler.invoke(SocketServerInstanceImpl.java:433) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.net.socket.SocketServerConnection$1.invoke(SocketServerConnection.java:293) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at com.sun.proxy.$Proxy24.closeRequest(Unknown Source) ~[?:?]
at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:164) ~[teiid-9.3.4-jdbc.jar:9.3.4]
... 9 more
Caused by: java.util.concurrent.ExecutionException: java.net.SocketException: Socket closed
at org.teiid.client.util.ResultsFuture.convertResult(ResultsFuture.java:104) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.client.util.ResultsFuture.get(ResultsFuture.java:99) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.net.socket.SocketServerInstanceImpl.send(SocketServerInstanceImpl.java:214) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at sun.reflect.GeneratedMethodAccessor24.invoke(Unknown Source) ~[?:?]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[?:1.8.0_121]
at java.lang.reflect.Method.invoke(Unknown Source) ~[?:1.8.0_121]
at org.teiid.net.socket.SocketServerConnectionFactory$ShutdownHandler.invoke(SocketServerConnectionFactory.java:98) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at com.sun.proxy.$Proxy21.send(Unknown Source) ~[?:?]
at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler.invoke(SocketServerInstanceImpl.java:433) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.net.socket.SocketServerConnection$1.invoke(SocketServerConnection.java:293) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at com.sun.proxy.$Proxy24.closeRequest(Unknown Source) ~[?:?]
at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:164) ~[teiid-9.3.4-jdbc.jar:9.3.4]
... 9 more
Caused by: java.net.SocketException: Socket closed
at java.net.SocketOutputStream.socketWrite(Unknown Source) ~[?:1.8.0_121]
at java.net.SocketOutputStream.write(Unknown Source) ~[?:1.8.0_121]
at java.io.DataOutputStream.write(Unknown Source) ~[?:1.8.0_121]
at org.teiid.core.util.MultiArrayOutputStream.writeTo(MultiArrayOutputStream.java:94) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.netty.handler.codec.serialization.ObjectEncoderOutputStream.writeObjectOverride(ObjectEncoderOutputStream.java:70) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at java.io.ObjectOutputStream.writeObject(Unknown Source) ~[?:1.8.0_121]
at org.teiid.net.socket.OioOjbectChannelFactory$OioObjectChannel.write(OioOjbectChannelFactory.java:136) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.net.socket.SocketServerInstanceImpl.send(SocketServerInstanceImpl.java:213) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at sun.reflect.GeneratedMethodAccessor24.invoke(Unknown Source) ~[?:?]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[?:1.8.0_121]
at java.lang.reflect.Method.invoke(Unknown Source) ~[?:1.8.0_121]
at org.teiid.net.socket.SocketServerConnectionFactory$ShutdownHandler.invoke(SocketServerConnectionFactory.java:98) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at com.sun.proxy.$Proxy21.send(Unknown Source) ~[?:?]
at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler.invoke(SocketServerInstanceImpl.java:433) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.net.socket.SocketServerConnection$1.invoke(SocketServerConnection.java:293) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at com.sun.proxy.$Proxy24.closeRequest(Unknown Source) ~[?:?]
at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:164) ~[teiid-9.3.4-jdbc.jar:9.3.4]
... 9 more
{code}
Server-side log excerpt, after raising logger levels to Debug:
{code}
2017-12-15 12:00:45.625 [NIO36 ] DEBUG - processing message:MessageHolder: key=550774 contents=Invoke interface org.teiid.client.DQP.executeRequest
2017-12-15 12:00:47.730 [ocessorQueue14017479] DEBUG - send message: MessageHolder: key=550774 contents=ResultsMessage rowCount=256 finalRow=-1
2017-12-15 12:00:47.737 [NIO36 ] DEBUG - processing message:MessageHolder: key=550776 contents=Invoke interface org.teiid.client.DQP.processCursorRequest
2017-12-15 12:00:47.738 [ocessorQueue14017553] DEBUG - send message: MessageHolder: key=550776 contents=ResultsMessage rowCount=2048 finalRow=-1
2017-12-15 12:00:47.755 [NIO36 ] DEBUG - processing message:MessageHolder: key=550777 contents=Invoke interface org.teiid.client.DQP.processCursorRequest
2017-12-15 12:00:47.756 [ocessorQueue14017554] DEBUG - send message: MessageHolder: key=550777 contents=ResultsMessage rowCount=2048 finalRow=-1
2017-12-15 12:00:48.389 [NIO36 ] DEBUG - processing message:MessageHolder: key=550778 contents=Invoke interface org.teiid.client.DQP.processCursorRequest
2017-12-15 12:00:48.389 [ocessorQueue14017556] DEBUG - send message: MessageHolder: key=550778 contents=ResultsMessage rowCount=2048 finalRow=-1
2017-12-15 12:00:48.825 [NIO36 ] DEBUG - processing message:MessageHolder: key=550779 contents=Invoke interface org.teiid.client.DQP.processCursorRequest
2017-12-15 12:00:48.826 [ocessorQueue14017557] DEBUG - send message: MessageHolder: key=550779 contents=ResultsMessage rowCount=2048 finalRow=-1
2017-12-15 12:00:48.932 [NIO36 ] DEBUG - processing message:MessageHolder: key=550780 contents=Invoke interface org.teiid.client.DQP.processCursorRequest
2017-12-15 12:00:48.933 [ocessorQueue14017558] DEBUG - send message: MessageHolder: key=550780 contents=ResultsMessage rowCount=2048 finalRow=-1
2017-12-15 12:02:18.386 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:05:55.327 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:09:29.545 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:13:08.903 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:16:41.864 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:20:16.875 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:23:57.860 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:27:30.273 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:31:07.795 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:34:46.439 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:38:23.325 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:41:59.227 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:45:35.526 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:49:14.088 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:52:46.177 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:56:24.407 [NIO36 ] DEBUG - Channel closed
2017-12-15 13:00:03.109 [NIO36 ] DEBUG - Channel closed
2017-12-15 13:00:52.143 [NIO36 ] DEBUG - TEIID40114 Unhandled exception, closing client instance: Connection reset by peer
java.io.IOException: Connection reset by peer
at sun.nio.ch.FileDispatcherImpl.read0(Native Method)
at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39)
at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:223)
at sun.nio.ch.IOUtil.read(IOUtil.java:192)
at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:380)
at io.netty.buffer.UnpooledUnsafeDirectByteBuf.setBytes(UnpooledUnsafeDirectByteBuf.java:447)
at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:880)
at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:242)
at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:119)
at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:511)
at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:468)
at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:382)
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:354)
at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:112)
at java.lang.Thread.run(Thread.java:745)
2017-12-15 13:00:52.143 [NIO36 ] DEBUG - Channel closed
2017-12-15 13:03:34.811 [NIO36 ] DEBUG - Channel closed
{code}
Legend:
* 'Channel closed' is logged from org.teiid.transport.SSLAwareChannelHandler class, and its channelInactive method;
* 'MessageHolder' logs are from org.teiid.net.socket.Message;
* the log lines that contain rowCount, finalRow, etc. are coming from org.teiid.transport.SocketClientInstance.
The problem is rarely reproducible, but it happens a few times every day, while running the JMeter tests full day.
We are also running JMeter in a scenario where the client is referring directly to a server URL, therefore skipping the VIP. We haven't been able to reproduce the problem in this setting so far, which suggests that the issue has something to do with the VIP setup.
was:
We have a server-side application that is powered by Teiid version 9.3.4, and that exposes a Teiid JDBC endpoint to its clients.
A couple of app instances are configured to sit behind a VIP load balancer, that works on the TCP level.
We have been experiencing intermittently following problem, when we run Teiid 9.3.4 client to execute multi-batch queries to the server:
* client successfully fetches few batches from server;
* client hangs and its thread blocks on waiting for the next batch to be delivered on the network;
* after 1 hour client throws exceptions that Socket is closed.
When building up the JDBC connection URL the client refers directly to the server's VIP, and does not list particular service hosts:
jdbc:teiid:<Application>@mm://<VIP's DNS name>:<port>
Client thread's call stack:
{code}
"Thread Group 1-1" #41 prio=6 os_prio=0 tid=0x000000005e03a800 nid=0x17bc runnable [0x00000000623ae000]
java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.socketRead(Unknown Source)
at java.net.SocketInputStream.read(Unknown Source)
at java.net.SocketInputStream.read(Unknown Source)
at java.io.BufferedInputStream.fill(Unknown Source)
at java.io.BufferedInputStream.read(Unknown Source)
- locked <0x00000000f5f32420> (a org.teiid.core.util.AccessibleBufferedInputStream)
at java.io.DataInputStream.readInt(Unknown Source)
at org.teiid.netty.handler.codec.serialization.ObjectDecoderInputStream.readObjectOverride(ObjectDecoderInputStream.java:97)
at java.io.ObjectInputStream.readObject(Unknown Source)
at org.teiid.net.socket.OioOjbectChannelFactory$OioObjectChannel.read(OioOjbectChannelFactory.java:117)
at org.teiid.net.socket.SocketServerInstanceImpl.read(SocketServerInstanceImpl.java:324)
at sun.reflect.GeneratedMethodAccessor22.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
at java.lang.reflect.Method.invoke(Unknown Source)
at org.teiid.net.socket.SocketServerConnectionFactory$ShutdownHandler.invoke(SocketServerConnectionFactory.java:98)
at com.sun.proxy.$Proxy21.read(Unknown Source)
at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler$1.get(SocketServerInstanceImpl.java:427)
at org.teiid.jdbc.ResultSetImpl.getResults(ResultSetImpl.java:449)
at org.teiid.jdbc.ResultSetImpl.requestBatch(ResultSetImpl.java:382)
at org.teiid.jdbc.BatchResults.requestBatchAndWait(BatchResults.java:227)
at org.teiid.jdbc.BatchResults.requestNextBatch(BatchResults.java:142)
at org.teiid.jdbc.BatchResults.hasNext(BatchResults.java:253)
at org.teiid.jdbc.ResultSetImpl.hasNext(ResultSetImpl.java:510)
at org.teiid.jdbc.ResultSetImpl.next(ResultSetImpl.java:259)
at org.apache.commons.dbcp2.DelegatingResultSet.next(DelegatingResultSet.java:191)
at org.apache.commons.dbcp2.DelegatingResultSet.next(DelegatingResultSet.java:191)
at org.apache.jmeter.protocol.jdbc.AbstractJDBCTestElement.getStringFromResultSet(AbstractJDBCTestElement.java:535)
at org.apache.jmeter.protocol.jdbc.AbstractJDBCTestElement.execute(AbstractJDBCTestElement.java:174)
at org.apache.jmeter.protocol.jdbc.sampler.JDBCSampler.sample(JDBCSampler.java:84)
at org.apache.jmeter.threads.JMeterThread.executeSamplePackage(JMeterThread.java:491)
at org.apache.jmeter.threads.JMeterThread.processSampler(JMeterThread.java:425)
at org.apache.jmeter.threads.JMeterThread.run(JMeterThread.java:254)
at java.lang.Thread.run(Unknown Source)
Locked ownable synchronizers:
- None
{code}
Client side exception after 1 hour:
{code}
2017-12-19 13:17:07,160 WARN o.a.j.p.j.AbstractJDBCTestElement: Error closing ResultSet
org.teiid.jdbc.TeiidSQLException: TEIID20013 java.net.SocketException: Socket closed
at org.teiid.jdbc.TeiidSQLException.create(TeiidSQLException.java:135) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.jdbc.TeiidSQLException.create(TeiidSQLException.java:71) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:168) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.apache.commons.dbcp2.DelegatingResultSet.close(DelegatingResultSet.java:170) ~[commons-dbcp2-2.1.1.jar:2.1.1]
at org.apache.commons.dbcp2.DelegatingResultSet.close(DelegatingResultSet.java:170) ~[commons-dbcp2-2.1.1.jar:2.1.1]
at org.apache.jmeter.protocol.jdbc.AbstractJDBCTestElement.close(AbstractJDBCTestElement.java:607) [ApacheJMeter_jdbc.jar:3.2 r1790748]
at org.apache.jmeter.protocol.jdbc.AbstractJDBCTestElement.execute(AbstractJDBCTestElement.java:176) [ApacheJMeter_jdbc.jar:3.2 r1790748]
at org.apache.jmeter.protocol.jdbc.sampler.JDBCSampler.sample(JDBCSampler.java:84) [ApacheJMeter_jdbc.jar:3.2 r1790748]
at org.apache.jmeter.threads.JMeterThread.executeSamplePackage(JMeterThread.java:491) [ApacheJMeter_core.jar:3.2 r1790748]
at org.apache.jmeter.threads.JMeterThread.processSampler(JMeterThread.java:425) [ApacheJMeter_core.jar:3.2 r1790748]
at org.apache.jmeter.threads.JMeterThread.run(JMeterThread.java:254) [ApacheJMeter_core.jar:3.2 r1790748]
at java.lang.Thread.run(Unknown Source) [?:1.8.0_121]
Caused by: org.teiid.core.TeiidComponentException: TEIID20013 java.net.SocketException: Socket closed
at org.teiid.client.util.ExceptionUtil.convertException(ExceptionUtil.java:65) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler.invoke(SocketServerInstanceImpl.java:445) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.net.socket.SocketServerConnection$1.invoke(SocketServerConnection.java:293) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at com.sun.proxy.$Proxy24.closeRequest(Unknown Source) ~[?:?]
at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:164) ~[teiid-9.3.4-jdbc.jar:9.3.4]
... 9 more
Caused by: org.teiid.net.socket.SingleInstanceCommunicationException: TEIID20013 java.net.SocketException: Socket closed
at org.teiid.net.socket.SocketServerInstanceImpl.send(SocketServerInstanceImpl.java:217) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at sun.reflect.GeneratedMethodAccessor24.invoke(Unknown Source) ~[?:?]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[?:1.8.0_121]
at java.lang.reflect.Method.invoke(Unknown Source) ~[?:1.8.0_121]
at org.teiid.net.socket.SocketServerConnectionFactory$ShutdownHandler.invoke(SocketServerConnectionFactory.java:98) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at com.sun.proxy.$Proxy21.send(Unknown Source) ~[?:?]
at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler.invoke(SocketServerInstanceImpl.java:433) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.net.socket.SocketServerConnection$1.invoke(SocketServerConnection.java:293) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at com.sun.proxy.$Proxy24.closeRequest(Unknown Source) ~[?:?]
at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:164) ~[teiid-9.3.4-jdbc.jar:9.3.4]
... 9 more
Caused by: java.util.concurrent.ExecutionException: java.net.SocketException: Socket closed
at org.teiid.client.util.ResultsFuture.convertResult(ResultsFuture.java:104) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.client.util.ResultsFuture.get(ResultsFuture.java:99) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.net.socket.SocketServerInstanceImpl.send(SocketServerInstanceImpl.java:214) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at sun.reflect.GeneratedMethodAccessor24.invoke(Unknown Source) ~[?:?]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[?:1.8.0_121]
at java.lang.reflect.Method.invoke(Unknown Source) ~[?:1.8.0_121]
at org.teiid.net.socket.SocketServerConnectionFactory$ShutdownHandler.invoke(SocketServerConnectionFactory.java:98) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at com.sun.proxy.$Proxy21.send(Unknown Source) ~[?:?]
at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler.invoke(SocketServerInstanceImpl.java:433) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.net.socket.SocketServerConnection$1.invoke(SocketServerConnection.java:293) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at com.sun.proxy.$Proxy24.closeRequest(Unknown Source) ~[?:?]
at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:164) ~[teiid-9.3.4-jdbc.jar:9.3.4]
... 9 more
Caused by: java.net.SocketException: Socket closed
at java.net.SocketOutputStream.socketWrite(Unknown Source) ~[?:1.8.0_121]
at java.net.SocketOutputStream.write(Unknown Source) ~[?:1.8.0_121]
at java.io.DataOutputStream.write(Unknown Source) ~[?:1.8.0_121]
at org.teiid.core.util.MultiArrayOutputStream.writeTo(MultiArrayOutputStream.java:94) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.netty.handler.codec.serialization.ObjectEncoderOutputStream.writeObjectOverride(ObjectEncoderOutputStream.java:70) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at java.io.ObjectOutputStream.writeObject(Unknown Source) ~[?:1.8.0_121]
at org.teiid.net.socket.OioOjbectChannelFactory$OioObjectChannel.write(OioOjbectChannelFactory.java:136) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.net.socket.SocketServerInstanceImpl.send(SocketServerInstanceImpl.java:213) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at sun.reflect.GeneratedMethodAccessor24.invoke(Unknown Source) ~[?:?]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[?:1.8.0_121]
at java.lang.reflect.Method.invoke(Unknown Source) ~[?:1.8.0_121]
at org.teiid.net.socket.SocketServerConnectionFactory$ShutdownHandler.invoke(SocketServerConnectionFactory.java:98) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at com.sun.proxy.$Proxy21.send(Unknown Source) ~[?:?]
at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler.invoke(SocketServerInstanceImpl.java:433) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.net.socket.SocketServerConnection$1.invoke(SocketServerConnection.java:293) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at com.sun.proxy.$Proxy24.closeRequest(Unknown Source) ~[?:?]
at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:164) ~[teiid-9.3.4-jdbc.jar:9.3.4]
... 9 more
{code}
Server-side log excerpt, after raising logger levels to Debug:
{code}
2017-12-15 12:00:45.625 [NIO36 ] DEBUG - processing message:MessageHolder: key=550774 contents=Invoke interface org.teiid.client.DQP.executeRequest
2017-12-15 12:00:47.730 [ocessorQueue14017479] DEBUG - send message: MessageHolder: key=550774 contents=ResultsMessage rowCount=256 finalRow=-1
2017-12-15 12:00:47.737 [NIO36 ] DEBUG - processing message:MessageHolder: key=550776 contents=Invoke interface org.teiid.client.DQP.processCursorRequest
2017-12-15 12:00:47.738 [ocessorQueue14017553] DEBUG - send message: MessageHolder: key=550776 contents=ResultsMessage rowCount=2048 finalRow=-1
2017-12-15 12:00:47.755 [NIO36 ] DEBUG - processing message:MessageHolder: key=550777 contents=Invoke interface org.teiid.client.DQP.processCursorRequest
2017-12-15 12:00:47.756 [ocessorQueue14017554] DEBUG - send message: MessageHolder: key=550777 contents=ResultsMessage rowCount=2048 finalRow=-1
2017-12-15 12:00:48.389 [NIO36 ] DEBUG - processing message:MessageHolder: key=550778 contents=Invoke interface org.teiid.client.DQP.processCursorRequest
2017-12-15 12:00:48.389 [ocessorQueue14017556] DEBUG - send message: MessageHolder: key=550778 contents=ResultsMessage rowCount=2048 finalRow=-1
2017-12-15 12:00:48.825 [NIO36 ] DEBUG - processing message:MessageHolder: key=550779 contents=Invoke interface org.teiid.client.DQP.processCursorRequest
2017-12-15 12:00:48.826 [ocessorQueue14017557] DEBUG - send message: MessageHolder: key=550779 contents=ResultsMessage rowCount=2048 finalRow=-1
2017-12-15 12:00:48.932 [NIO36 ] DEBUG - processing message:MessageHolder: key=550780 contents=Invoke interface org.teiid.client.DQP.processCursorRequest
2017-12-15 12:00:48.933 [ocessorQueue14017558] DEBUG - send message: MessageHolder: key=550780 contents=ResultsMessage rowCount=2048 finalRow=-1
2017-12-15 12:02:18.386 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:05:55.327 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:09:29.545 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:13:08.903 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:16:41.864 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:20:16.875 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:23:57.860 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:27:30.273 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:31:07.795 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:34:46.439 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:38:23.325 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:41:59.227 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:45:35.526 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:49:14.088 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:52:46.177 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:56:24.407 [NIO36 ] DEBUG - Channel closed
2017-12-15 13:00:03.109 [NIO36 ] DEBUG - Channel closed
2017-12-15 13:00:52.143 [NIO36 ] DEBUG - TEIID40114 Unhandled exception, closing client instance: Connection reset by peer
java.io.IOException: Connection reset by peer
at sun.nio.ch.FileDispatcherImpl.read0(Native Method)
at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39)
at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:223)
at sun.nio.ch.IOUtil.read(IOUtil.java:192)
at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:380)
at io.netty.buffer.UnpooledUnsafeDirectByteBuf.setBytes(UnpooledUnsafeDirectByteBuf.java:447)
at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:880)
at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:242)
at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:119)
at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:511)
at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:468)
at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:382)
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:354)
at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:112)
at java.lang.Thread.run(Thread.java:745)
2017-12-15 13:00:52.143 [NIO36 ] DEBUG - Channel closed
2017-12-15 13:03:34.811 [NIO36 ] DEBUG - Channel closed
{code}
Legend:
* 'Channel closed' is logged from org.teiid.transport.SSLAwareChannelHandler class, and its channelInactive method;
* 'MessageHolder' logs are from org.teiid.net.socket.Message;
* the log lines that contain rowCount, finalRow, etc. are coming from org.teiid.transport.SocketClientInstance.
The problem is rarely reproducible, but it happens a few times every day, while running the JMeter tests full day.
We are also running JMeter in a scenario where the client is referring directly to a serv
> JDBC client intermittently hangs when processing multi-batch result sets from server
> ------------------------------------------------------------------------------------
>
> Key: TEIID-5185
> URL: https://issues.jboss.org/browse/TEIID-5185
> Project: Teiid
> Issue Type: Bug
> Components: JDBC Driver, Server
> Affects Versions: 9.3.4
> Environment: JDBC client was run through Apache JMeter, on a 64-bit Windows 7 Enterprise SP1 machine, using 64-bit JDK 8;
> Teiid Server runs on Linux.
> Reporter: Krum Bakalsky
> Assignee: Steven Hawkins
>
> We have a server-side application that is powered by Teiid version 9.3.4, and that exposes a Teiid JDBC endpoint to its clients.
> A couple of app instances are configured to sit behind a VIP load balancer, that works on the TCP level.
> We have been experiencing intermittently following problem, when we run Teiid 9.3.4 client to execute multi-batch queries to the server:
> * client successfully fetches few batches from server;
> * client hangs and its thread blocks on waiting for the next batch to be delivered on the network;
> * after 1 hour client throws exceptions that Socket is closed.
> When building up the JDBC connection URL the client refers directly to the server's VIP, and does not list particular server hosts:
> jdbc:teiid:<Application>@mm://<VIP's DNS name>:<port>
> Client thread's call stack:
> {code}
> "Thread Group 1-1" #41 prio=6 os_prio=0 tid=0x000000005e03a800 nid=0x17bc runnable [0x00000000623ae000]
> java.lang.Thread.State: RUNNABLE
> at java.net.SocketInputStream.socketRead0(Native Method)
> at java.net.SocketInputStream.socketRead(Unknown Source)
> at java.net.SocketInputStream.read(Unknown Source)
> at java.net.SocketInputStream.read(Unknown Source)
> at java.io.BufferedInputStream.fill(Unknown Source)
> at java.io.BufferedInputStream.read(Unknown Source)
> - locked <0x00000000f5f32420> (a org.teiid.core.util.AccessibleBufferedInputStream)
> at java.io.DataInputStream.readInt(Unknown Source)
> at org.teiid.netty.handler.codec.serialization.ObjectDecoderInputStream.readObjectOverride(ObjectDecoderInputStream.java:97)
> at java.io.ObjectInputStream.readObject(Unknown Source)
> at org.teiid.net.socket.OioOjbectChannelFactory$OioObjectChannel.read(OioOjbectChannelFactory.java:117)
> at org.teiid.net.socket.SocketServerInstanceImpl.read(SocketServerInstanceImpl.java:324)
> at sun.reflect.GeneratedMethodAccessor22.invoke(Unknown Source)
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
> at java.lang.reflect.Method.invoke(Unknown Source)
> at org.teiid.net.socket.SocketServerConnectionFactory$ShutdownHandler.invoke(SocketServerConnectionFactory.java:98)
> at com.sun.proxy.$Proxy21.read(Unknown Source)
> at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler$1.get(SocketServerInstanceImpl.java:427)
> at org.teiid.jdbc.ResultSetImpl.getResults(ResultSetImpl.java:449)
> at org.teiid.jdbc.ResultSetImpl.requestBatch(ResultSetImpl.java:382)
> at org.teiid.jdbc.BatchResults.requestBatchAndWait(BatchResults.java:227)
> at org.teiid.jdbc.BatchResults.requestNextBatch(BatchResults.java:142)
> at org.teiid.jdbc.BatchResults.hasNext(BatchResults.java:253)
> at org.teiid.jdbc.ResultSetImpl.hasNext(ResultSetImpl.java:510)
> at org.teiid.jdbc.ResultSetImpl.next(ResultSetImpl.java:259)
> at org.apache.commons.dbcp2.DelegatingResultSet.next(DelegatingResultSet.java:191)
> at org.apache.commons.dbcp2.DelegatingResultSet.next(DelegatingResultSet.java:191)
> at org.apache.jmeter.protocol.jdbc.AbstractJDBCTestElement.getStringFromResultSet(AbstractJDBCTestElement.java:535)
> at org.apache.jmeter.protocol.jdbc.AbstractJDBCTestElement.execute(AbstractJDBCTestElement.java:174)
> at org.apache.jmeter.protocol.jdbc.sampler.JDBCSampler.sample(JDBCSampler.java:84)
> at org.apache.jmeter.threads.JMeterThread.executeSamplePackage(JMeterThread.java:491)
> at org.apache.jmeter.threads.JMeterThread.processSampler(JMeterThread.java:425)
> at org.apache.jmeter.threads.JMeterThread.run(JMeterThread.java:254)
> at java.lang.Thread.run(Unknown Source)
> Locked ownable synchronizers:
> - None
> {code}
> Client side exception after 1 hour:
> {code}
> 2017-12-19 13:17:07,160 WARN o.a.j.p.j.AbstractJDBCTestElement: Error closing ResultSet
> org.teiid.jdbc.TeiidSQLException: TEIID20013 java.net.SocketException: Socket closed
> at org.teiid.jdbc.TeiidSQLException.create(TeiidSQLException.java:135) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.teiid.jdbc.TeiidSQLException.create(TeiidSQLException.java:71) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:168) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.apache.commons.dbcp2.DelegatingResultSet.close(DelegatingResultSet.java:170) ~[commons-dbcp2-2.1.1.jar:2.1.1]
> at org.apache.commons.dbcp2.DelegatingResultSet.close(DelegatingResultSet.java:170) ~[commons-dbcp2-2.1.1.jar:2.1.1]
> at org.apache.jmeter.protocol.jdbc.AbstractJDBCTestElement.close(AbstractJDBCTestElement.java:607) [ApacheJMeter_jdbc.jar:3.2 r1790748]
> at org.apache.jmeter.protocol.jdbc.AbstractJDBCTestElement.execute(AbstractJDBCTestElement.java:176) [ApacheJMeter_jdbc.jar:3.2 r1790748]
> at org.apache.jmeter.protocol.jdbc.sampler.JDBCSampler.sample(JDBCSampler.java:84) [ApacheJMeter_jdbc.jar:3.2 r1790748]
> at org.apache.jmeter.threads.JMeterThread.executeSamplePackage(JMeterThread.java:491) [ApacheJMeter_core.jar:3.2 r1790748]
> at org.apache.jmeter.threads.JMeterThread.processSampler(JMeterThread.java:425) [ApacheJMeter_core.jar:3.2 r1790748]
> at org.apache.jmeter.threads.JMeterThread.run(JMeterThread.java:254) [ApacheJMeter_core.jar:3.2 r1790748]
> at java.lang.Thread.run(Unknown Source) [?:1.8.0_121]
> Caused by: org.teiid.core.TeiidComponentException: TEIID20013 java.net.SocketException: Socket closed
> at org.teiid.client.util.ExceptionUtil.convertException(ExceptionUtil.java:65) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler.invoke(SocketServerInstanceImpl.java:445) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.teiid.net.socket.SocketServerConnection$1.invoke(SocketServerConnection.java:293) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at com.sun.proxy.$Proxy24.closeRequest(Unknown Source) ~[?:?]
> at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:164) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> ... 9 more
> Caused by: org.teiid.net.socket.SingleInstanceCommunicationException: TEIID20013 java.net.SocketException: Socket closed
> at org.teiid.net.socket.SocketServerInstanceImpl.send(SocketServerInstanceImpl.java:217) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at sun.reflect.GeneratedMethodAccessor24.invoke(Unknown Source) ~[?:?]
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[?:1.8.0_121]
> at java.lang.reflect.Method.invoke(Unknown Source) ~[?:1.8.0_121]
> at org.teiid.net.socket.SocketServerConnectionFactory$ShutdownHandler.invoke(SocketServerConnectionFactory.java:98) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at com.sun.proxy.$Proxy21.send(Unknown Source) ~[?:?]
> at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler.invoke(SocketServerInstanceImpl.java:433) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.teiid.net.socket.SocketServerConnection$1.invoke(SocketServerConnection.java:293) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at com.sun.proxy.$Proxy24.closeRequest(Unknown Source) ~[?:?]
> at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:164) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> ... 9 more
> Caused by: java.util.concurrent.ExecutionException: java.net.SocketException: Socket closed
> at org.teiid.client.util.ResultsFuture.convertResult(ResultsFuture.java:104) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.teiid.client.util.ResultsFuture.get(ResultsFuture.java:99) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.teiid.net.socket.SocketServerInstanceImpl.send(SocketServerInstanceImpl.java:214) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at sun.reflect.GeneratedMethodAccessor24.invoke(Unknown Source) ~[?:?]
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[?:1.8.0_121]
> at java.lang.reflect.Method.invoke(Unknown Source) ~[?:1.8.0_121]
> at org.teiid.net.socket.SocketServerConnectionFactory$ShutdownHandler.invoke(SocketServerConnectionFactory.java:98) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at com.sun.proxy.$Proxy21.send(Unknown Source) ~[?:?]
> at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler.invoke(SocketServerInstanceImpl.java:433) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.teiid.net.socket.SocketServerConnection$1.invoke(SocketServerConnection.java:293) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at com.sun.proxy.$Proxy24.closeRequest(Unknown Source) ~[?:?]
> at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:164) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> ... 9 more
> Caused by: java.net.SocketException: Socket closed
> at java.net.SocketOutputStream.socketWrite(Unknown Source) ~[?:1.8.0_121]
> at java.net.SocketOutputStream.write(Unknown Source) ~[?:1.8.0_121]
> at java.io.DataOutputStream.write(Unknown Source) ~[?:1.8.0_121]
> at org.teiid.core.util.MultiArrayOutputStream.writeTo(MultiArrayOutputStream.java:94) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.teiid.netty.handler.codec.serialization.ObjectEncoderOutputStream.writeObjectOverride(ObjectEncoderOutputStream.java:70) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at java.io.ObjectOutputStream.writeObject(Unknown Source) ~[?:1.8.0_121]
> at org.teiid.net.socket.OioOjbectChannelFactory$OioObjectChannel.write(OioOjbectChannelFactory.java:136) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.teiid.net.socket.SocketServerInstanceImpl.send(SocketServerInstanceImpl.java:213) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at sun.reflect.GeneratedMethodAccessor24.invoke(Unknown Source) ~[?:?]
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[?:1.8.0_121]
> at java.lang.reflect.Method.invoke(Unknown Source) ~[?:1.8.0_121]
> at org.teiid.net.socket.SocketServerConnectionFactory$ShutdownHandler.invoke(SocketServerConnectionFactory.java:98) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at com.sun.proxy.$Proxy21.send(Unknown Source) ~[?:?]
> at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler.invoke(SocketServerInstanceImpl.java:433) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.teiid.net.socket.SocketServerConnection$1.invoke(SocketServerConnection.java:293) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at com.sun.proxy.$Proxy24.closeRequest(Unknown Source) ~[?:?]
> at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:164) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> ... 9 more
> {code}
> Server-side log excerpt, after raising logger levels to Debug:
> {code}
> 2017-12-15 12:00:45.625 [NIO36 ] DEBUG - processing message:MessageHolder: key=550774 contents=Invoke interface org.teiid.client.DQP.executeRequest
> 2017-12-15 12:00:47.730 [ocessorQueue14017479] DEBUG - send message: MessageHolder: key=550774 contents=ResultsMessage rowCount=256 finalRow=-1
> 2017-12-15 12:00:47.737 [NIO36 ] DEBUG - processing message:MessageHolder: key=550776 contents=Invoke interface org.teiid.client.DQP.processCursorRequest
> 2017-12-15 12:00:47.738 [ocessorQueue14017553] DEBUG - send message: MessageHolder: key=550776 contents=ResultsMessage rowCount=2048 finalRow=-1
> 2017-12-15 12:00:47.755 [NIO36 ] DEBUG - processing message:MessageHolder: key=550777 contents=Invoke interface org.teiid.client.DQP.processCursorRequest
> 2017-12-15 12:00:47.756 [ocessorQueue14017554] DEBUG - send message: MessageHolder: key=550777 contents=ResultsMessage rowCount=2048 finalRow=-1
> 2017-12-15 12:00:48.389 [NIO36 ] DEBUG - processing message:MessageHolder: key=550778 contents=Invoke interface org.teiid.client.DQP.processCursorRequest
> 2017-12-15 12:00:48.389 [ocessorQueue14017556] DEBUG - send message: MessageHolder: key=550778 contents=ResultsMessage rowCount=2048 finalRow=-1
> 2017-12-15 12:00:48.825 [NIO36 ] DEBUG - processing message:MessageHolder: key=550779 contents=Invoke interface org.teiid.client.DQP.processCursorRequest
> 2017-12-15 12:00:48.826 [ocessorQueue14017557] DEBUG - send message: MessageHolder: key=550779 contents=ResultsMessage rowCount=2048 finalRow=-1
> 2017-12-15 12:00:48.932 [NIO36 ] DEBUG - processing message:MessageHolder: key=550780 contents=Invoke interface org.teiid.client.DQP.processCursorRequest
> 2017-12-15 12:00:48.933 [ocessorQueue14017558] DEBUG - send message: MessageHolder: key=550780 contents=ResultsMessage rowCount=2048 finalRow=-1
> 2017-12-15 12:02:18.386 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:05:55.327 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:09:29.545 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:13:08.903 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:16:41.864 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:20:16.875 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:23:57.860 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:27:30.273 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:31:07.795 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:34:46.439 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:38:23.325 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:41:59.227 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:45:35.526 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:49:14.088 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:52:46.177 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:56:24.407 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 13:00:03.109 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 13:00:52.143 [NIO36 ] DEBUG - TEIID40114 Unhandled exception, closing client instance: Connection reset by peer
> java.io.IOException: Connection reset by peer
> at sun.nio.ch.FileDispatcherImpl.read0(Native Method)
> at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39)
> at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:223)
> at sun.nio.ch.IOUtil.read(IOUtil.java:192)
> at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:380)
> at io.netty.buffer.UnpooledUnsafeDirectByteBuf.setBytes(UnpooledUnsafeDirectByteBuf.java:447)
> at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:880)
> at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:242)
> at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:119)
> at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:511)
> at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:468)
> at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:382)
> at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:354)
> at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:112)
> at java.lang.Thread.run(Thread.java:745)
> 2017-12-15 13:00:52.143 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 13:03:34.811 [NIO36 ] DEBUG - Channel closed
> {code}
> Legend:
> * 'Channel closed' is logged from org.teiid.transport.SSLAwareChannelHandler class, and its channelInactive method;
> * 'MessageHolder' logs are from org.teiid.net.socket.Message;
> * the log lines that contain rowCount, finalRow, etc. are coming from org.teiid.transport.SocketClientInstance.
> The problem is rarely reproducible, but it happens a few times every day, while running the JMeter tests full day.
> We are also running JMeter in a scenario where the client is referring directly to a server URL, therefore skipping the VIP. We haven't been able to reproduce the problem in this setting so far, which suggests that the issue has something to do with the VIP setup.
--
This message was sent by Atlassian JIRA
(v7.5.0#75005)
6 years, 4 months
- 1
- 0
[JBoss JIRA] (TEIID-5185) JDBC client intermittently hangs when processing multi-batch result sets from VIPped Teiid server
by Krum Bakalsky (JIRA)
[ https://issues.jboss.org/browse/TEIID-5185?page=com.atlassian.jira.plugin... ]
Krum Bakalsky updated TEIID-5185:
---------------------------------
Summary: JDBC client intermittently hangs when processing multi-batch result sets from VIPped Teiid server (was: JDBC client intermittently hangs when processing multi-batch result sets from server)
> JDBC client intermittently hangs when processing multi-batch result sets from VIPped Teiid server
> -------------------------------------------------------------------------------------------------
>
> Key: TEIID-5185
> URL: https://issues.jboss.org/browse/TEIID-5185
> Project: Teiid
> Issue Type: Bug
> Components: JDBC Driver, Server
> Affects Versions: 9.3.4
> Environment: JDBC client was run through Apache JMeter, on a 64-bit Windows 7 Enterprise SP1 machine, using 64-bit JDK 8;
> Teiid Server runs on Linux.
> Reporter: Krum Bakalsky
> Assignee: Steven Hawkins
>
> We have a server-side application that is powered by Teiid version 9.3.4, and that exposes a Teiid JDBC endpoint to its clients.
> A couple of app instances are configured to sit behind a VIP load balancer, that works on the TCP level.
> We have been experiencing intermittently following problem, when we run Teiid 9.3.4 client to execute multi-batch queries to the server:
> * client successfully fetches few batches from server;
> * client hangs and its thread blocks on waiting for the next batch to be delivered on the network;
> * after 1 hour client throws exceptions that Socket is closed.
> When building up the JDBC connection URL the client refers directly to the server's VIP, and does not list particular server hosts:
> jdbc:teiid:<Application>@mm://<VIP's DNS name>:<port>
> Client thread's call stack:
> {code}
> "Thread Group 1-1" #41 prio=6 os_prio=0 tid=0x000000005e03a800 nid=0x17bc runnable [0x00000000623ae000]
> java.lang.Thread.State: RUNNABLE
> at java.net.SocketInputStream.socketRead0(Native Method)
> at java.net.SocketInputStream.socketRead(Unknown Source)
> at java.net.SocketInputStream.read(Unknown Source)
> at java.net.SocketInputStream.read(Unknown Source)
> at java.io.BufferedInputStream.fill(Unknown Source)
> at java.io.BufferedInputStream.read(Unknown Source)
> - locked <0x00000000f5f32420> (a org.teiid.core.util.AccessibleBufferedInputStream)
> at java.io.DataInputStream.readInt(Unknown Source)
> at org.teiid.netty.handler.codec.serialization.ObjectDecoderInputStream.readObjectOverride(ObjectDecoderInputStream.java:97)
> at java.io.ObjectInputStream.readObject(Unknown Source)
> at org.teiid.net.socket.OioOjbectChannelFactory$OioObjectChannel.read(OioOjbectChannelFactory.java:117)
> at org.teiid.net.socket.SocketServerInstanceImpl.read(SocketServerInstanceImpl.java:324)
> at sun.reflect.GeneratedMethodAccessor22.invoke(Unknown Source)
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
> at java.lang.reflect.Method.invoke(Unknown Source)
> at org.teiid.net.socket.SocketServerConnectionFactory$ShutdownHandler.invoke(SocketServerConnectionFactory.java:98)
> at com.sun.proxy.$Proxy21.read(Unknown Source)
> at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler$1.get(SocketServerInstanceImpl.java:427)
> at org.teiid.jdbc.ResultSetImpl.getResults(ResultSetImpl.java:449)
> at org.teiid.jdbc.ResultSetImpl.requestBatch(ResultSetImpl.java:382)
> at org.teiid.jdbc.BatchResults.requestBatchAndWait(BatchResults.java:227)
> at org.teiid.jdbc.BatchResults.requestNextBatch(BatchResults.java:142)
> at org.teiid.jdbc.BatchResults.hasNext(BatchResults.java:253)
> at org.teiid.jdbc.ResultSetImpl.hasNext(ResultSetImpl.java:510)
> at org.teiid.jdbc.ResultSetImpl.next(ResultSetImpl.java:259)
> at org.apache.commons.dbcp2.DelegatingResultSet.next(DelegatingResultSet.java:191)
> at org.apache.commons.dbcp2.DelegatingResultSet.next(DelegatingResultSet.java:191)
> at org.apache.jmeter.protocol.jdbc.AbstractJDBCTestElement.getStringFromResultSet(AbstractJDBCTestElement.java:535)
> at org.apache.jmeter.protocol.jdbc.AbstractJDBCTestElement.execute(AbstractJDBCTestElement.java:174)
> at org.apache.jmeter.protocol.jdbc.sampler.JDBCSampler.sample(JDBCSampler.java:84)
> at org.apache.jmeter.threads.JMeterThread.executeSamplePackage(JMeterThread.java:491)
> at org.apache.jmeter.threads.JMeterThread.processSampler(JMeterThread.java:425)
> at org.apache.jmeter.threads.JMeterThread.run(JMeterThread.java:254)
> at java.lang.Thread.run(Unknown Source)
> Locked ownable synchronizers:
> - None
> {code}
> Client side exception after 1 hour:
> {code}
> 2017-12-19 13:17:07,160 WARN o.a.j.p.j.AbstractJDBCTestElement: Error closing ResultSet
> org.teiid.jdbc.TeiidSQLException: TEIID20013 java.net.SocketException: Socket closed
> at org.teiid.jdbc.TeiidSQLException.create(TeiidSQLException.java:135) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.teiid.jdbc.TeiidSQLException.create(TeiidSQLException.java:71) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:168) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.apache.commons.dbcp2.DelegatingResultSet.close(DelegatingResultSet.java:170) ~[commons-dbcp2-2.1.1.jar:2.1.1]
> at org.apache.commons.dbcp2.DelegatingResultSet.close(DelegatingResultSet.java:170) ~[commons-dbcp2-2.1.1.jar:2.1.1]
> at org.apache.jmeter.protocol.jdbc.AbstractJDBCTestElement.close(AbstractJDBCTestElement.java:607) [ApacheJMeter_jdbc.jar:3.2 r1790748]
> at org.apache.jmeter.protocol.jdbc.AbstractJDBCTestElement.execute(AbstractJDBCTestElement.java:176) [ApacheJMeter_jdbc.jar:3.2 r1790748]
> at org.apache.jmeter.protocol.jdbc.sampler.JDBCSampler.sample(JDBCSampler.java:84) [ApacheJMeter_jdbc.jar:3.2 r1790748]
> at org.apache.jmeter.threads.JMeterThread.executeSamplePackage(JMeterThread.java:491) [ApacheJMeter_core.jar:3.2 r1790748]
> at org.apache.jmeter.threads.JMeterThread.processSampler(JMeterThread.java:425) [ApacheJMeter_core.jar:3.2 r1790748]
> at org.apache.jmeter.threads.JMeterThread.run(JMeterThread.java:254) [ApacheJMeter_core.jar:3.2 r1790748]
> at java.lang.Thread.run(Unknown Source) [?:1.8.0_121]
> Caused by: org.teiid.core.TeiidComponentException: TEIID20013 java.net.SocketException: Socket closed
> at org.teiid.client.util.ExceptionUtil.convertException(ExceptionUtil.java:65) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler.invoke(SocketServerInstanceImpl.java:445) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.teiid.net.socket.SocketServerConnection$1.invoke(SocketServerConnection.java:293) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at com.sun.proxy.$Proxy24.closeRequest(Unknown Source) ~[?:?]
> at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:164) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> ... 9 more
> Caused by: org.teiid.net.socket.SingleInstanceCommunicationException: TEIID20013 java.net.SocketException: Socket closed
> at org.teiid.net.socket.SocketServerInstanceImpl.send(SocketServerInstanceImpl.java:217) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at sun.reflect.GeneratedMethodAccessor24.invoke(Unknown Source) ~[?:?]
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[?:1.8.0_121]
> at java.lang.reflect.Method.invoke(Unknown Source) ~[?:1.8.0_121]
> at org.teiid.net.socket.SocketServerConnectionFactory$ShutdownHandler.invoke(SocketServerConnectionFactory.java:98) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at com.sun.proxy.$Proxy21.send(Unknown Source) ~[?:?]
> at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler.invoke(SocketServerInstanceImpl.java:433) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.teiid.net.socket.SocketServerConnection$1.invoke(SocketServerConnection.java:293) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at com.sun.proxy.$Proxy24.closeRequest(Unknown Source) ~[?:?]
> at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:164) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> ... 9 more
> Caused by: java.util.concurrent.ExecutionException: java.net.SocketException: Socket closed
> at org.teiid.client.util.ResultsFuture.convertResult(ResultsFuture.java:104) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.teiid.client.util.ResultsFuture.get(ResultsFuture.java:99) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.teiid.net.socket.SocketServerInstanceImpl.send(SocketServerInstanceImpl.java:214) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at sun.reflect.GeneratedMethodAccessor24.invoke(Unknown Source) ~[?:?]
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[?:1.8.0_121]
> at java.lang.reflect.Method.invoke(Unknown Source) ~[?:1.8.0_121]
> at org.teiid.net.socket.SocketServerConnectionFactory$ShutdownHandler.invoke(SocketServerConnectionFactory.java:98) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at com.sun.proxy.$Proxy21.send(Unknown Source) ~[?:?]
> at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler.invoke(SocketServerInstanceImpl.java:433) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.teiid.net.socket.SocketServerConnection$1.invoke(SocketServerConnection.java:293) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at com.sun.proxy.$Proxy24.closeRequest(Unknown Source) ~[?:?]
> at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:164) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> ... 9 more
> Caused by: java.net.SocketException: Socket closed
> at java.net.SocketOutputStream.socketWrite(Unknown Source) ~[?:1.8.0_121]
> at java.net.SocketOutputStream.write(Unknown Source) ~[?:1.8.0_121]
> at java.io.DataOutputStream.write(Unknown Source) ~[?:1.8.0_121]
> at org.teiid.core.util.MultiArrayOutputStream.writeTo(MultiArrayOutputStream.java:94) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.teiid.netty.handler.codec.serialization.ObjectEncoderOutputStream.writeObjectOverride(ObjectEncoderOutputStream.java:70) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at java.io.ObjectOutputStream.writeObject(Unknown Source) ~[?:1.8.0_121]
> at org.teiid.net.socket.OioOjbectChannelFactory$OioObjectChannel.write(OioOjbectChannelFactory.java:136) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.teiid.net.socket.SocketServerInstanceImpl.send(SocketServerInstanceImpl.java:213) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at sun.reflect.GeneratedMethodAccessor24.invoke(Unknown Source) ~[?:?]
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[?:1.8.0_121]
> at java.lang.reflect.Method.invoke(Unknown Source) ~[?:1.8.0_121]
> at org.teiid.net.socket.SocketServerConnectionFactory$ShutdownHandler.invoke(SocketServerConnectionFactory.java:98) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at com.sun.proxy.$Proxy21.send(Unknown Source) ~[?:?]
> at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler.invoke(SocketServerInstanceImpl.java:433) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.teiid.net.socket.SocketServerConnection$1.invoke(SocketServerConnection.java:293) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at com.sun.proxy.$Proxy24.closeRequest(Unknown Source) ~[?:?]
> at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:164) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> ... 9 more
> {code}
> Server-side log excerpt, after raising logger levels to Debug:
> {code}
> 2017-12-15 12:00:45.625 [NIO36 ] DEBUG - processing message:MessageHolder: key=550774 contents=Invoke interface org.teiid.client.DQP.executeRequest
> 2017-12-15 12:00:47.730 [ocessorQueue14017479] DEBUG - send message: MessageHolder: key=550774 contents=ResultsMessage rowCount=256 finalRow=-1
> 2017-12-15 12:00:47.737 [NIO36 ] DEBUG - processing message:MessageHolder: key=550776 contents=Invoke interface org.teiid.client.DQP.processCursorRequest
> 2017-12-15 12:00:47.738 [ocessorQueue14017553] DEBUG - send message: MessageHolder: key=550776 contents=ResultsMessage rowCount=2048 finalRow=-1
> 2017-12-15 12:00:47.755 [NIO36 ] DEBUG - processing message:MessageHolder: key=550777 contents=Invoke interface org.teiid.client.DQP.processCursorRequest
> 2017-12-15 12:00:47.756 [ocessorQueue14017554] DEBUG - send message: MessageHolder: key=550777 contents=ResultsMessage rowCount=2048 finalRow=-1
> 2017-12-15 12:00:48.389 [NIO36 ] DEBUG - processing message:MessageHolder: key=550778 contents=Invoke interface org.teiid.client.DQP.processCursorRequest
> 2017-12-15 12:00:48.389 [ocessorQueue14017556] DEBUG - send message: MessageHolder: key=550778 contents=ResultsMessage rowCount=2048 finalRow=-1
> 2017-12-15 12:00:48.825 [NIO36 ] DEBUG - processing message:MessageHolder: key=550779 contents=Invoke interface org.teiid.client.DQP.processCursorRequest
> 2017-12-15 12:00:48.826 [ocessorQueue14017557] DEBUG - send message: MessageHolder: key=550779 contents=ResultsMessage rowCount=2048 finalRow=-1
> 2017-12-15 12:00:48.932 [NIO36 ] DEBUG - processing message:MessageHolder: key=550780 contents=Invoke interface org.teiid.client.DQP.processCursorRequest
> 2017-12-15 12:00:48.933 [ocessorQueue14017558] DEBUG - send message: MessageHolder: key=550780 contents=ResultsMessage rowCount=2048 finalRow=-1
> 2017-12-15 12:02:18.386 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:05:55.327 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:09:29.545 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:13:08.903 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:16:41.864 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:20:16.875 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:23:57.860 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:27:30.273 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:31:07.795 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:34:46.439 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:38:23.325 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:41:59.227 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:45:35.526 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:49:14.088 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:52:46.177 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:56:24.407 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 13:00:03.109 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 13:00:52.143 [NIO36 ] DEBUG - TEIID40114 Unhandled exception, closing client instance: Connection reset by peer
> java.io.IOException: Connection reset by peer
> at sun.nio.ch.FileDispatcherImpl.read0(Native Method)
> at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39)
> at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:223)
> at sun.nio.ch.IOUtil.read(IOUtil.java:192)
> at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:380)
> at io.netty.buffer.UnpooledUnsafeDirectByteBuf.setBytes(UnpooledUnsafeDirectByteBuf.java:447)
> at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:880)
> at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:242)
> at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:119)
> at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:511)
> at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:468)
> at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:382)
> at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:354)
> at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:112)
> at java.lang.Thread.run(Thread.java:745)
> 2017-12-15 13:00:52.143 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 13:03:34.811 [NIO36 ] DEBUG - Channel closed
> {code}
> Legend:
> * 'Channel closed' is logged from org.teiid.transport.SSLAwareChannelHandler class, and its channelInactive method;
> * 'MessageHolder' logs are from org.teiid.net.socket.Message;
> * the log lines that contain rowCount, finalRow, etc. are coming from org.teiid.transport.SocketClientInstance.
> The problem is rarely reproducible, but it happens a few times every day, while running the JMeter tests full day.
> We are also running JMeter in a scenario where the client is referring directly to a server URL, therefore skipping the VIP. We haven't been able to reproduce the problem in this setting so far, which suggests that the issue has something to do with the VIP setup.
--
This message was sent by Atlassian JIRA
(v7.5.0#75005)
6 years, 4 months
- 1
- 0
[JBoss JIRA] (TEIID-5185) JDBC client intermittently hangs when processing multi-batch result sets from server
by Krum Bakalsky (JIRA)
[ https://issues.jboss.org/browse/TEIID-5185?page=com.atlassian.jira.plugin... ]
Krum Bakalsky updated TEIID-5185:
---------------------------------
Description:
We have a server-side application that is powered by Teiid version 9.3.4, and that exposes a Teiid JDBC endpoint to its clients.
A couple of app instances are configured to sit behind a VIP load balancer, that works on the TCP level.
We have been experiencing intermittently following problem, when we run Teiid 9.3.4 client to execute multi-batch queries to the server:
* client successfully fetches few batches from server;
* client hangs and its thread blocks on waiting for the next batch to be delivered on the network;
* after 1 hour client throws exceptions that Socket is closed.
When building up the JDBC connection URL the client refers directly to the server's VIP, and does not list particular service hosts:
jdbc:teiid:<Application>@mm://<VIP's DNS name>:<port>
Client thread's call stack:
{code}
"Thread Group 1-1" #41 prio=6 os_prio=0 tid=0x000000005e03a800 nid=0x17bc runnable [0x00000000623ae000]
java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.socketRead(Unknown Source)
at java.net.SocketInputStream.read(Unknown Source)
at java.net.SocketInputStream.read(Unknown Source)
at java.io.BufferedInputStream.fill(Unknown Source)
at java.io.BufferedInputStream.read(Unknown Source)
- locked <0x00000000f5f32420> (a org.teiid.core.util.AccessibleBufferedInputStream)
at java.io.DataInputStream.readInt(Unknown Source)
at org.teiid.netty.handler.codec.serialization.ObjectDecoderInputStream.readObjectOverride(ObjectDecoderInputStream.java:97)
at java.io.ObjectInputStream.readObject(Unknown Source)
at org.teiid.net.socket.OioOjbectChannelFactory$OioObjectChannel.read(OioOjbectChannelFactory.java:117)
at org.teiid.net.socket.SocketServerInstanceImpl.read(SocketServerInstanceImpl.java:324)
at sun.reflect.GeneratedMethodAccessor22.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
at java.lang.reflect.Method.invoke(Unknown Source)
at org.teiid.net.socket.SocketServerConnectionFactory$ShutdownHandler.invoke(SocketServerConnectionFactory.java:98)
at com.sun.proxy.$Proxy21.read(Unknown Source)
at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler$1.get(SocketServerInstanceImpl.java:427)
at org.teiid.jdbc.ResultSetImpl.getResults(ResultSetImpl.java:449)
at org.teiid.jdbc.ResultSetImpl.requestBatch(ResultSetImpl.java:382)
at org.teiid.jdbc.BatchResults.requestBatchAndWait(BatchResults.java:227)
at org.teiid.jdbc.BatchResults.requestNextBatch(BatchResults.java:142)
at org.teiid.jdbc.BatchResults.hasNext(BatchResults.java:253)
at org.teiid.jdbc.ResultSetImpl.hasNext(ResultSetImpl.java:510)
at org.teiid.jdbc.ResultSetImpl.next(ResultSetImpl.java:259)
at org.apache.commons.dbcp2.DelegatingResultSet.next(DelegatingResultSet.java:191)
at org.apache.commons.dbcp2.DelegatingResultSet.next(DelegatingResultSet.java:191)
at org.apache.jmeter.protocol.jdbc.AbstractJDBCTestElement.getStringFromResultSet(AbstractJDBCTestElement.java:535)
at org.apache.jmeter.protocol.jdbc.AbstractJDBCTestElement.execute(AbstractJDBCTestElement.java:174)
at org.apache.jmeter.protocol.jdbc.sampler.JDBCSampler.sample(JDBCSampler.java:84)
at org.apache.jmeter.threads.JMeterThread.executeSamplePackage(JMeterThread.java:491)
at org.apache.jmeter.threads.JMeterThread.processSampler(JMeterThread.java:425)
at org.apache.jmeter.threads.JMeterThread.run(JMeterThread.java:254)
at java.lang.Thread.run(Unknown Source)
Locked ownable synchronizers:
- None
{code}
Client side exception after 1 hour:
{code}
2017-12-19 13:17:07,160 WARN o.a.j.p.j.AbstractJDBCTestElement: Error closing ResultSet
org.teiid.jdbc.TeiidSQLException: TEIID20013 java.net.SocketException: Socket closed
at org.teiid.jdbc.TeiidSQLException.create(TeiidSQLException.java:135) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.jdbc.TeiidSQLException.create(TeiidSQLException.java:71) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:168) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.apache.commons.dbcp2.DelegatingResultSet.close(DelegatingResultSet.java:170) ~[commons-dbcp2-2.1.1.jar:2.1.1]
at org.apache.commons.dbcp2.DelegatingResultSet.close(DelegatingResultSet.java:170) ~[commons-dbcp2-2.1.1.jar:2.1.1]
at org.apache.jmeter.protocol.jdbc.AbstractJDBCTestElement.close(AbstractJDBCTestElement.java:607) [ApacheJMeter_jdbc.jar:3.2 r1790748]
at org.apache.jmeter.protocol.jdbc.AbstractJDBCTestElement.execute(AbstractJDBCTestElement.java:176) [ApacheJMeter_jdbc.jar:3.2 r1790748]
at org.apache.jmeter.protocol.jdbc.sampler.JDBCSampler.sample(JDBCSampler.java:84) [ApacheJMeter_jdbc.jar:3.2 r1790748]
at org.apache.jmeter.threads.JMeterThread.executeSamplePackage(JMeterThread.java:491) [ApacheJMeter_core.jar:3.2 r1790748]
at org.apache.jmeter.threads.JMeterThread.processSampler(JMeterThread.java:425) [ApacheJMeter_core.jar:3.2 r1790748]
at org.apache.jmeter.threads.JMeterThread.run(JMeterThread.java:254) [ApacheJMeter_core.jar:3.2 r1790748]
at java.lang.Thread.run(Unknown Source) [?:1.8.0_121]
Caused by: org.teiid.core.TeiidComponentException: TEIID20013 java.net.SocketException: Socket closed
at org.teiid.client.util.ExceptionUtil.convertException(ExceptionUtil.java:65) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler.invoke(SocketServerInstanceImpl.java:445) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.net.socket.SocketServerConnection$1.invoke(SocketServerConnection.java:293) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at com.sun.proxy.$Proxy24.closeRequest(Unknown Source) ~[?:?]
at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:164) ~[teiid-9.3.4-jdbc.jar:9.3.4]
... 9 more
Caused by: org.teiid.net.socket.SingleInstanceCommunicationException: TEIID20013 java.net.SocketException: Socket closed
at org.teiid.net.socket.SocketServerInstanceImpl.send(SocketServerInstanceImpl.java:217) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at sun.reflect.GeneratedMethodAccessor24.invoke(Unknown Source) ~[?:?]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[?:1.8.0_121]
at java.lang.reflect.Method.invoke(Unknown Source) ~[?:1.8.0_121]
at org.teiid.net.socket.SocketServerConnectionFactory$ShutdownHandler.invoke(SocketServerConnectionFactory.java:98) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at com.sun.proxy.$Proxy21.send(Unknown Source) ~[?:?]
at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler.invoke(SocketServerInstanceImpl.java:433) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.net.socket.SocketServerConnection$1.invoke(SocketServerConnection.java:293) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at com.sun.proxy.$Proxy24.closeRequest(Unknown Source) ~[?:?]
at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:164) ~[teiid-9.3.4-jdbc.jar:9.3.4]
... 9 more
Caused by: java.util.concurrent.ExecutionException: java.net.SocketException: Socket closed
at org.teiid.client.util.ResultsFuture.convertResult(ResultsFuture.java:104) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.client.util.ResultsFuture.get(ResultsFuture.java:99) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.net.socket.SocketServerInstanceImpl.send(SocketServerInstanceImpl.java:214) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at sun.reflect.GeneratedMethodAccessor24.invoke(Unknown Source) ~[?:?]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[?:1.8.0_121]
at java.lang.reflect.Method.invoke(Unknown Source) ~[?:1.8.0_121]
at org.teiid.net.socket.SocketServerConnectionFactory$ShutdownHandler.invoke(SocketServerConnectionFactory.java:98) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at com.sun.proxy.$Proxy21.send(Unknown Source) ~[?:?]
at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler.invoke(SocketServerInstanceImpl.java:433) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.net.socket.SocketServerConnection$1.invoke(SocketServerConnection.java:293) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at com.sun.proxy.$Proxy24.closeRequest(Unknown Source) ~[?:?]
at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:164) ~[teiid-9.3.4-jdbc.jar:9.3.4]
... 9 more
Caused by: java.net.SocketException: Socket closed
at java.net.SocketOutputStream.socketWrite(Unknown Source) ~[?:1.8.0_121]
at java.net.SocketOutputStream.write(Unknown Source) ~[?:1.8.0_121]
at java.io.DataOutputStream.write(Unknown Source) ~[?:1.8.0_121]
at org.teiid.core.util.MultiArrayOutputStream.writeTo(MultiArrayOutputStream.java:94) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.netty.handler.codec.serialization.ObjectEncoderOutputStream.writeObjectOverride(ObjectEncoderOutputStream.java:70) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at java.io.ObjectOutputStream.writeObject(Unknown Source) ~[?:1.8.0_121]
at org.teiid.net.socket.OioOjbectChannelFactory$OioObjectChannel.write(OioOjbectChannelFactory.java:136) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.net.socket.SocketServerInstanceImpl.send(SocketServerInstanceImpl.java:213) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at sun.reflect.GeneratedMethodAccessor24.invoke(Unknown Source) ~[?:?]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[?:1.8.0_121]
at java.lang.reflect.Method.invoke(Unknown Source) ~[?:1.8.0_121]
at org.teiid.net.socket.SocketServerConnectionFactory$ShutdownHandler.invoke(SocketServerConnectionFactory.java:98) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at com.sun.proxy.$Proxy21.send(Unknown Source) ~[?:?]
at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler.invoke(SocketServerInstanceImpl.java:433) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.net.socket.SocketServerConnection$1.invoke(SocketServerConnection.java:293) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at com.sun.proxy.$Proxy24.closeRequest(Unknown Source) ~[?:?]
at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:164) ~[teiid-9.3.4-jdbc.jar:9.3.4]
... 9 more
{code}
Server-side log excerpt, after raising logger levels to Debug:
{code}
2017-12-15 12:00:45.625 [NIO36 ] DEBUG - processing message:MessageHolder: key=550774 contents=Invoke interface org.teiid.client.DQP.executeRequest
2017-12-15 12:00:47.730 [ocessorQueue14017479] DEBUG - send message: MessageHolder: key=550774 contents=ResultsMessage rowCount=256 finalRow=-1
2017-12-15 12:00:47.737 [NIO36 ] DEBUG - processing message:MessageHolder: key=550776 contents=Invoke interface org.teiid.client.DQP.processCursorRequest
2017-12-15 12:00:47.738 [ocessorQueue14017553] DEBUG - send message: MessageHolder: key=550776 contents=ResultsMessage rowCount=2048 finalRow=-1
2017-12-15 12:00:47.755 [NIO36 ] DEBUG - processing message:MessageHolder: key=550777 contents=Invoke interface org.teiid.client.DQP.processCursorRequest
2017-12-15 12:00:47.756 [ocessorQueue14017554] DEBUG - send message: MessageHolder: key=550777 contents=ResultsMessage rowCount=2048 finalRow=-1
2017-12-15 12:00:48.389 [NIO36 ] DEBUG - processing message:MessageHolder: key=550778 contents=Invoke interface org.teiid.client.DQP.processCursorRequest
2017-12-15 12:00:48.389 [ocessorQueue14017556] DEBUG - send message: MessageHolder: key=550778 contents=ResultsMessage rowCount=2048 finalRow=-1
2017-12-15 12:00:48.825 [NIO36 ] DEBUG - processing message:MessageHolder: key=550779 contents=Invoke interface org.teiid.client.DQP.processCursorRequest
2017-12-15 12:00:48.826 [ocessorQueue14017557] DEBUG - send message: MessageHolder: key=550779 contents=ResultsMessage rowCount=2048 finalRow=-1
2017-12-15 12:00:48.932 [NIO36 ] DEBUG - processing message:MessageHolder: key=550780 contents=Invoke interface org.teiid.client.DQP.processCursorRequest
2017-12-15 12:00:48.933 [ocessorQueue14017558] DEBUG - send message: MessageHolder: key=550780 contents=ResultsMessage rowCount=2048 finalRow=-1
2017-12-15 12:02:18.386 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:05:55.327 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:09:29.545 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:13:08.903 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:16:41.864 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:20:16.875 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:23:57.860 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:27:30.273 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:31:07.795 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:34:46.439 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:38:23.325 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:41:59.227 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:45:35.526 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:49:14.088 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:52:46.177 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:56:24.407 [NIO36 ] DEBUG - Channel closed
2017-12-15 13:00:03.109 [NIO36 ] DEBUG - Channel closed
2017-12-15 13:00:52.143 [NIO36 ] DEBUG - TEIID40114 Unhandled exception, closing client instance: Connection reset by peer
java.io.IOException: Connection reset by peer
at sun.nio.ch.FileDispatcherImpl.read0(Native Method)
at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39)
at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:223)
at sun.nio.ch.IOUtil.read(IOUtil.java:192)
at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:380)
at io.netty.buffer.UnpooledUnsafeDirectByteBuf.setBytes(UnpooledUnsafeDirectByteBuf.java:447)
at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:880)
at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:242)
at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:119)
at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:511)
at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:468)
at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:382)
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:354)
at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:112)
at java.lang.Thread.run(Thread.java:745)
2017-12-15 13:00:52.143 [NIO36 ] DEBUG - Channel closed
2017-12-15 13:03:34.811 [NIO36 ] DEBUG - Channel closed
{code}
Legend:
* 'Channel closed' is logged from org.teiid.transport.SSLAwareChannelHandler class, and its channelInactive method;
* 'MessageHolder' logs are from org.teiid.net.socket.Message;
* the log lines that contain rowCount, finalRow, etc. are coming from org.teiid.transport.SocketClientInstance.
The problem is rarely reproducible, but it happens a few times every day, while running the JMeter tests full day.
We are also running JMeter in a scenario where the client is referring directly to a serv
was:
We have a server-side application that is powered by Teiid version 9.3.4, and that exposes a Teiid JDBC endpoint to its clients.
A couple of app instances are configured to sit behind a VIP load balancer, that works on the TCP level.
We have been experiencing intermittently following problem, when we run Teiid 9.3.4 client to execute multi-batch queries to the server:
* client successfully fetches few batches from server;
* client hangs and its thread blocks on waiting for the next batch to be delivered on the network;
* after 1 hour client throws exceptions that Socket is closed.
When building up the JDBC connection URL the client refers directly to the server's VIP, and does not list particular service hosts:
jdbc:teiid:<Application>@mm://<VIP's DNS name>:<port>
Client thread's call stack:
{code}
"Thread Group 1-1" #41 prio=6 os_prio=0 tid=0x000000005e03a800 nid=0x17bc runnable [0x00000000623ae000]
java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.socketRead(Unknown Source)
at java.net.SocketInputStream.read(Unknown Source)
at java.net.SocketInputStream.read(Unknown Source)
at java.io.BufferedInputStream.fill(Unknown Source)
at java.io.BufferedInputStream.read(Unknown Source)
- locked <0x00000000f5f32420> (a org.teiid.core.util.AccessibleBufferedInputStream)
at java.io.DataInputStream.readInt(Unknown Source)
at org.teiid.netty.handler.codec.serialization.ObjectDecoderInputStream.readObjectOverride(ObjectDecoderInputStream.java:97)
at java.io.ObjectInputStream.readObject(Unknown Source)
at org.teiid.net.socket.OioOjbectChannelFactory$OioObjectChannel.read(OioOjbectChannelFactory.java:117)
at org.teiid.net.socket.SocketServerInstanceImpl.read(SocketServerInstanceImpl.java:324)
at sun.reflect.GeneratedMethodAccessor22.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
at java.lang.reflect.Method.invoke(Unknown Source)
at org.teiid.net.socket.SocketServerConnectionFactory$ShutdownHandler.invoke(SocketServerConnectionFactory.java:98)
at com.sun.proxy.$Proxy21.read(Unknown Source)
at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler$1.get(SocketServerInstanceImpl.java:427)
at org.teiid.jdbc.ResultSetImpl.getResults(ResultSetImpl.java:449)
at org.teiid.jdbc.ResultSetImpl.requestBatch(ResultSetImpl.java:382)
at org.teiid.jdbc.BatchResults.requestBatchAndWait(BatchResults.java:227)
at org.teiid.jdbc.BatchResults.requestNextBatch(BatchResults.java:142)
at org.teiid.jdbc.BatchResults.hasNext(BatchResults.java:253)
at org.teiid.jdbc.ResultSetImpl.hasNext(ResultSetImpl.java:510)
at org.teiid.jdbc.ResultSetImpl.next(ResultSetImpl.java:259)
at org.apache.commons.dbcp2.DelegatingResultSet.next(DelegatingResultSet.java:191)
at org.apache.commons.dbcp2.DelegatingResultSet.next(DelegatingResultSet.java:191)
at org.apache.jmeter.protocol.jdbc.AbstractJDBCTestElement.getStringFromResultSet(AbstractJDBCTestElement.java:535)
at org.apache.jmeter.protocol.jdbc.AbstractJDBCTestElement.execute(AbstractJDBCTestElement.java:174)
at org.apache.jmeter.protocol.jdbc.sampler.JDBCSampler.sample(JDBCSampler.java:84)
at org.apache.jmeter.threads.JMeterThread.executeSamplePackage(JMeterThread.java:491)
at org.apache.jmeter.threads.JMeterThread.processSampler(JMeterThread.java:425)
at org.apache.jmeter.threads.JMeterThread.run(JMeterThread.java:254)
at java.lang.Thread.run(Unknown Source)
Locked ownable synchronizers:
- None
{code}
Client side exception after 1 hour:
{code}
2017-12-19 13:17:07,160 WARN o.a.j.p.j.AbstractJDBCTestElement: Error closing ResultSet
org.teiid.jdbc.TeiidSQLException: TEIID20013 java.net.SocketException: Socket closed
at org.teiid.jdbc.TeiidSQLException.create(TeiidSQLException.java:135) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.jdbc.TeiidSQLException.create(TeiidSQLException.java:71) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:168) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.apache.commons.dbcp2.DelegatingResultSet.close(DelegatingResultSet.java:170) ~[commons-dbcp2-2.1.1.jar:2.1.1]
at org.apache.commons.dbcp2.DelegatingResultSet.close(DelegatingResultSet.java:170) ~[commons-dbcp2-2.1.1.jar:2.1.1]
at org.apache.jmeter.protocol.jdbc.AbstractJDBCTestElement.close(AbstractJDBCTestElement.java:607) [ApacheJMeter_jdbc.jar:3.2 r1790748]
at org.apache.jmeter.protocol.jdbc.AbstractJDBCTestElement.execute(AbstractJDBCTestElement.java:176) [ApacheJMeter_jdbc.jar:3.2 r1790748]
at org.apache.jmeter.protocol.jdbc.sampler.JDBCSampler.sample(JDBCSampler.java:84) [ApacheJMeter_jdbc.jar:3.2 r1790748]
at org.apache.jmeter.threads.JMeterThread.executeSamplePackage(JMeterThread.java:491) [ApacheJMeter_core.jar:3.2 r1790748]
at org.apache.jmeter.threads.JMeterThread.processSampler(JMeterThread.java:425) [ApacheJMeter_core.jar:3.2 r1790748]
at org.apache.jmeter.threads.JMeterThread.run(JMeterThread.java:254) [ApacheJMeter_core.jar:3.2 r1790748]
at java.lang.Thread.run(Unknown Source) [?:1.8.0_121]
Caused by: org.teiid.core.TeiidComponentException: TEIID20013 java.net.SocketException: Socket closed
at org.teiid.client.util.ExceptionUtil.convertException(ExceptionUtil.java:65) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler.invoke(SocketServerInstanceImpl.java:445) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.net.socket.SocketServerConnection$1.invoke(SocketServerConnection.java:293) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at com.sun.proxy.$Proxy24.closeRequest(Unknown Source) ~[?:?]
at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:164) ~[teiid-9.3.4-jdbc.jar:9.3.4]
... 9 more
Caused by: org.teiid.net.socket.SingleInstanceCommunicationException: TEIID20013 java.net.SocketException: Socket closed
at org.teiid.net.socket.SocketServerInstanceImpl.send(SocketServerInstanceImpl.java:217) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at sun.reflect.GeneratedMethodAccessor24.invoke(Unknown Source) ~[?:?]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[?:1.8.0_121]
at java.lang.reflect.Method.invoke(Unknown Source) ~[?:1.8.0_121]
at org.teiid.net.socket.SocketServerConnectionFactory$ShutdownHandler.invoke(SocketServerConnectionFactory.java:98) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at com.sun.proxy.$Proxy21.send(Unknown Source) ~[?:?]
at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler.invoke(SocketServerInstanceImpl.java:433) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.net.socket.SocketServerConnection$1.invoke(SocketServerConnection.java:293) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at com.sun.proxy.$Proxy24.closeRequest(Unknown Source) ~[?:?]
at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:164) ~[teiid-9.3.4-jdbc.jar:9.3.4]
... 9 more
Caused by: java.util.concurrent.ExecutionException: java.net.SocketException: Socket closed
at org.teiid.client.util.ResultsFuture.convertResult(ResultsFuture.java:104) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.client.util.ResultsFuture.get(ResultsFuture.java:99) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.net.socket.SocketServerInstanceImpl.send(SocketServerInstanceImpl.java:214) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at sun.reflect.GeneratedMethodAccessor24.invoke(Unknown Source) ~[?:?]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[?:1.8.0_121]
at java.lang.reflect.Method.invoke(Unknown Source) ~[?:1.8.0_121]
at org.teiid.net.socket.SocketServerConnectionFactory$ShutdownHandler.invoke(SocketServerConnectionFactory.java:98) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at com.sun.proxy.$Proxy21.send(Unknown Source) ~[?:?]
at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler.invoke(SocketServerInstanceImpl.java:433) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.net.socket.SocketServerConnection$1.invoke(SocketServerConnection.java:293) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at com.sun.proxy.$Proxy24.closeRequest(Unknown Source) ~[?:?]
at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:164) ~[teiid-9.3.4-jdbc.jar:9.3.4]
... 9 more
Caused by: java.net.SocketException: Socket closed
at java.net.SocketOutputStream.socketWrite(Unknown Source) ~[?:1.8.0_121]
at java.net.SocketOutputStream.write(Unknown Source) ~[?:1.8.0_121]
at java.io.DataOutputStream.write(Unknown Source) ~[?:1.8.0_121]
at org.teiid.core.util.MultiArrayOutputStream.writeTo(MultiArrayOutputStream.java:94) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.netty.handler.codec.serialization.ObjectEncoderOutputStream.writeObjectOverride(ObjectEncoderOutputStream.java:70) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at java.io.ObjectOutputStream.writeObject(Unknown Source) ~[?:1.8.0_121]
at org.teiid.net.socket.OioOjbectChannelFactory$OioObjectChannel.write(OioOjbectChannelFactory.java:136) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.net.socket.SocketServerInstanceImpl.send(SocketServerInstanceImpl.java:213) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at sun.reflect.GeneratedMethodAccessor24.invoke(Unknown Source) ~[?:?]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[?:1.8.0_121]
at java.lang.reflect.Method.invoke(Unknown Source) ~[?:1.8.0_121]
at org.teiid.net.socket.SocketServerConnectionFactory$ShutdownHandler.invoke(SocketServerConnectionFactory.java:98) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at com.sun.proxy.$Proxy21.send(Unknown Source) ~[?:?]
at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler.invoke(SocketServerInstanceImpl.java:433) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.net.socket.SocketServerConnection$1.invoke(SocketServerConnection.java:293) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at com.sun.proxy.$Proxy24.closeRequest(Unknown Source) ~[?:?]
at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:164) ~[teiid-9.3.4-jdbc.jar:9.3.4]
... 9 more
{code}
Server-side log excerpt, after raising logger levels to Debug:
{code}
2017-12-15 12:00:45.625 [NIO36 ] DEBUG - processing message:MessageHolder: key=550774 contents=Invoke interface org.teiid.client.DQP.executeRequest
2017-12-15 12:00:47.730 [ocessorQueue14017479] DEBUG - send message: MessageHolder: key=550774 contents=ResultsMessage rowCount=256 finalRow=-1
2017-12-15 12:00:47.737 [NIO36 ] DEBUG - processing message:MessageHolder: key=550776 contents=Invoke interface org.teiid.client.DQP.processCursorRequest
2017-12-15 12:00:47.738 [ocessorQueue14017553] DEBUG - send message: MessageHolder: key=550776 contents=ResultsMessage rowCount=2048 finalRow=-1
2017-12-15 12:00:47.755 [NIO36 ] DEBUG - processing message:MessageHolder: key=550777 contents=Invoke interface org.teiid.client.DQP.processCursorRequest
2017-12-15 12:00:47.756 [ocessorQueue14017554] DEBUG - send message: MessageHolder: key=550777 contents=ResultsMessage rowCount=2048 finalRow=-1
2017-12-15 12:00:48.389 [NIO36 ] DEBUG - processing message:MessageHolder: key=550778 contents=Invoke interface org.teiid.client.DQP.processCursorRequest
2017-12-15 12:00:48.389 [ocessorQueue14017556] DEBUG - send message: MessageHolder: key=550778 contents=ResultsMessage rowCount=2048 finalRow=-1
2017-12-15 12:00:48.825 [NIO36 ] DEBUG - processing message:MessageHolder: key=550779 contents=Invoke interface org.teiid.client.DQP.processCursorRequest
2017-12-15 12:00:48.826 [ocessorQueue14017557] DEBUG - send message: MessageHolder: key=550779 contents=ResultsMessage rowCount=2048 finalRow=-1
2017-12-15 12:00:48.932 [NIO36 ] DEBUG - processing message:MessageHolder: key=550780 contents=Invoke interface org.teiid.client.DQP.processCursorRequest
2017-12-15 12:00:48.933 [ocessorQueue14017558] DEBUG - send message: MessageHolder: key=550780 contents=ResultsMessage rowCount=2048 finalRow=-1
2017-12-15 12:02:18.386 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:05:55.327 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:09:29.545 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:13:08.903 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:16:41.864 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:20:16.875 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:23:57.860 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:27:30.273 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:31:07.795 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:34:46.439 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:38:23.325 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:41:59.227 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:45:35.526 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:49:14.088 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:52:46.177 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:56:24.407 [NIO36 ] DEBUG - Channel closed
2017-12-15 13:00:03.109 [NIO36 ] DEBUG - Channel closed
2017-12-15 13:00:52.143 [NIO36 ] DEBUG - TEIID40114 Unhandled exception, closing client instance: Connection reset by peer
java.io.IOException: Connection reset by peer
at sun.nio.ch.FileDispatcherImpl.read0(Native Method)
at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39)
at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:223)
at sun.nio.ch.IOUtil.read(IOUtil.java:192)
at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:380)
at io.netty.buffer.UnpooledUnsafeDirectByteBuf.setBytes(UnpooledUnsafeDirectByteBuf.java:447)
at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:880)
at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:242)
at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:119)
at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:511)
at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:468)
at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:382)
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:354)
at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:112)
at java.lang.Thread.run(Thread.java:745)
2017-12-15 13:00:52.143 [NIO36 ] DEBUG - Channel closed
2017-12-15 13:03:34.811 [NIO36 ] DEBUG - Channel closed
{code}
Legend:
* 'Channel closed' is logged from org.teiid.transport.SSLAwareChannelHandler class, and its channelInactive method;
* 'MessageHolder' logs are from org.teiid.net.socket.Message;
* the log lines that contain rowCount, finalRow, etc. are coming from org.teiid.transport.SocketClientInstance.
The problem is rarely reproducible, but it happens a few times every day, while running the JMeter tests full day.
W
> JDBC client intermittently hangs when processing multi-batch result sets from server
> ------------------------------------------------------------------------------------
>
> Key: TEIID-5185
> URL: https://issues.jboss.org/browse/TEIID-5185
> Project: Teiid
> Issue Type: Bug
> Components: JDBC Driver, Server
> Affects Versions: 9.3.4
> Environment: JDBC client was run through Apache JMeter, on a 64-bit Windows 7 Enterprise SP1 machine, using 64-bit JDK 8;
> Teiid Server runs on Linux.
> Reporter: Krum Bakalsky
> Assignee: Steven Hawkins
>
> We have a server-side application that is powered by Teiid version 9.3.4, and that exposes a Teiid JDBC endpoint to its clients.
> A couple of app instances are configured to sit behind a VIP load balancer, that works on the TCP level.
> We have been experiencing intermittently following problem, when we run Teiid 9.3.4 client to execute multi-batch queries to the server:
> * client successfully fetches few batches from server;
> * client hangs and its thread blocks on waiting for the next batch to be delivered on the network;
> * after 1 hour client throws exceptions that Socket is closed.
> When building up the JDBC connection URL the client refers directly to the server's VIP, and does not list particular service hosts:
> jdbc:teiid:<Application>@mm://<VIP's DNS name>:<port>
> Client thread's call stack:
> {code}
> "Thread Group 1-1" #41 prio=6 os_prio=0 tid=0x000000005e03a800 nid=0x17bc runnable [0x00000000623ae000]
> java.lang.Thread.State: RUNNABLE
> at java.net.SocketInputStream.socketRead0(Native Method)
> at java.net.SocketInputStream.socketRead(Unknown Source)
> at java.net.SocketInputStream.read(Unknown Source)
> at java.net.SocketInputStream.read(Unknown Source)
> at java.io.BufferedInputStream.fill(Unknown Source)
> at java.io.BufferedInputStream.read(Unknown Source)
> - locked <0x00000000f5f32420> (a org.teiid.core.util.AccessibleBufferedInputStream)
> at java.io.DataInputStream.readInt(Unknown Source)
> at org.teiid.netty.handler.codec.serialization.ObjectDecoderInputStream.readObjectOverride(ObjectDecoderInputStream.java:97)
> at java.io.ObjectInputStream.readObject(Unknown Source)
> at org.teiid.net.socket.OioOjbectChannelFactory$OioObjectChannel.read(OioOjbectChannelFactory.java:117)
> at org.teiid.net.socket.SocketServerInstanceImpl.read(SocketServerInstanceImpl.java:324)
> at sun.reflect.GeneratedMethodAccessor22.invoke(Unknown Source)
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
> at java.lang.reflect.Method.invoke(Unknown Source)
> at org.teiid.net.socket.SocketServerConnectionFactory$ShutdownHandler.invoke(SocketServerConnectionFactory.java:98)
> at com.sun.proxy.$Proxy21.read(Unknown Source)
> at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler$1.get(SocketServerInstanceImpl.java:427)
> at org.teiid.jdbc.ResultSetImpl.getResults(ResultSetImpl.java:449)
> at org.teiid.jdbc.ResultSetImpl.requestBatch(ResultSetImpl.java:382)
> at org.teiid.jdbc.BatchResults.requestBatchAndWait(BatchResults.java:227)
> at org.teiid.jdbc.BatchResults.requestNextBatch(BatchResults.java:142)
> at org.teiid.jdbc.BatchResults.hasNext(BatchResults.java:253)
> at org.teiid.jdbc.ResultSetImpl.hasNext(ResultSetImpl.java:510)
> at org.teiid.jdbc.ResultSetImpl.next(ResultSetImpl.java:259)
> at org.apache.commons.dbcp2.DelegatingResultSet.next(DelegatingResultSet.java:191)
> at org.apache.commons.dbcp2.DelegatingResultSet.next(DelegatingResultSet.java:191)
> at org.apache.jmeter.protocol.jdbc.AbstractJDBCTestElement.getStringFromResultSet(AbstractJDBCTestElement.java:535)
> at org.apache.jmeter.protocol.jdbc.AbstractJDBCTestElement.execute(AbstractJDBCTestElement.java:174)
> at org.apache.jmeter.protocol.jdbc.sampler.JDBCSampler.sample(JDBCSampler.java:84)
> at org.apache.jmeter.threads.JMeterThread.executeSamplePackage(JMeterThread.java:491)
> at org.apache.jmeter.threads.JMeterThread.processSampler(JMeterThread.java:425)
> at org.apache.jmeter.threads.JMeterThread.run(JMeterThread.java:254)
> at java.lang.Thread.run(Unknown Source)
> Locked ownable synchronizers:
> - None
> {code}
> Client side exception after 1 hour:
> {code}
> 2017-12-19 13:17:07,160 WARN o.a.j.p.j.AbstractJDBCTestElement: Error closing ResultSet
> org.teiid.jdbc.TeiidSQLException: TEIID20013 java.net.SocketException: Socket closed
> at org.teiid.jdbc.TeiidSQLException.create(TeiidSQLException.java:135) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.teiid.jdbc.TeiidSQLException.create(TeiidSQLException.java:71) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:168) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.apache.commons.dbcp2.DelegatingResultSet.close(DelegatingResultSet.java:170) ~[commons-dbcp2-2.1.1.jar:2.1.1]
> at org.apache.commons.dbcp2.DelegatingResultSet.close(DelegatingResultSet.java:170) ~[commons-dbcp2-2.1.1.jar:2.1.1]
> at org.apache.jmeter.protocol.jdbc.AbstractJDBCTestElement.close(AbstractJDBCTestElement.java:607) [ApacheJMeter_jdbc.jar:3.2 r1790748]
> at org.apache.jmeter.protocol.jdbc.AbstractJDBCTestElement.execute(AbstractJDBCTestElement.java:176) [ApacheJMeter_jdbc.jar:3.2 r1790748]
> at org.apache.jmeter.protocol.jdbc.sampler.JDBCSampler.sample(JDBCSampler.java:84) [ApacheJMeter_jdbc.jar:3.2 r1790748]
> at org.apache.jmeter.threads.JMeterThread.executeSamplePackage(JMeterThread.java:491) [ApacheJMeter_core.jar:3.2 r1790748]
> at org.apache.jmeter.threads.JMeterThread.processSampler(JMeterThread.java:425) [ApacheJMeter_core.jar:3.2 r1790748]
> at org.apache.jmeter.threads.JMeterThread.run(JMeterThread.java:254) [ApacheJMeter_core.jar:3.2 r1790748]
> at java.lang.Thread.run(Unknown Source) [?:1.8.0_121]
> Caused by: org.teiid.core.TeiidComponentException: TEIID20013 java.net.SocketException: Socket closed
> at org.teiid.client.util.ExceptionUtil.convertException(ExceptionUtil.java:65) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler.invoke(SocketServerInstanceImpl.java:445) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.teiid.net.socket.SocketServerConnection$1.invoke(SocketServerConnection.java:293) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at com.sun.proxy.$Proxy24.closeRequest(Unknown Source) ~[?:?]
> at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:164) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> ... 9 more
> Caused by: org.teiid.net.socket.SingleInstanceCommunicationException: TEIID20013 java.net.SocketException: Socket closed
> at org.teiid.net.socket.SocketServerInstanceImpl.send(SocketServerInstanceImpl.java:217) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at sun.reflect.GeneratedMethodAccessor24.invoke(Unknown Source) ~[?:?]
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[?:1.8.0_121]
> at java.lang.reflect.Method.invoke(Unknown Source) ~[?:1.8.0_121]
> at org.teiid.net.socket.SocketServerConnectionFactory$ShutdownHandler.invoke(SocketServerConnectionFactory.java:98) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at com.sun.proxy.$Proxy21.send(Unknown Source) ~[?:?]
> at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler.invoke(SocketServerInstanceImpl.java:433) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.teiid.net.socket.SocketServerConnection$1.invoke(SocketServerConnection.java:293) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at com.sun.proxy.$Proxy24.closeRequest(Unknown Source) ~[?:?]
> at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:164) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> ... 9 more
> Caused by: java.util.concurrent.ExecutionException: java.net.SocketException: Socket closed
> at org.teiid.client.util.ResultsFuture.convertResult(ResultsFuture.java:104) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.teiid.client.util.ResultsFuture.get(ResultsFuture.java:99) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.teiid.net.socket.SocketServerInstanceImpl.send(SocketServerInstanceImpl.java:214) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at sun.reflect.GeneratedMethodAccessor24.invoke(Unknown Source) ~[?:?]
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[?:1.8.0_121]
> at java.lang.reflect.Method.invoke(Unknown Source) ~[?:1.8.0_121]
> at org.teiid.net.socket.SocketServerConnectionFactory$ShutdownHandler.invoke(SocketServerConnectionFactory.java:98) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at com.sun.proxy.$Proxy21.send(Unknown Source) ~[?:?]
> at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler.invoke(SocketServerInstanceImpl.java:433) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.teiid.net.socket.SocketServerConnection$1.invoke(SocketServerConnection.java:293) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at com.sun.proxy.$Proxy24.closeRequest(Unknown Source) ~[?:?]
> at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:164) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> ... 9 more
> Caused by: java.net.SocketException: Socket closed
> at java.net.SocketOutputStream.socketWrite(Unknown Source) ~[?:1.8.0_121]
> at java.net.SocketOutputStream.write(Unknown Source) ~[?:1.8.0_121]
> at java.io.DataOutputStream.write(Unknown Source) ~[?:1.8.0_121]
> at org.teiid.core.util.MultiArrayOutputStream.writeTo(MultiArrayOutputStream.java:94) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.teiid.netty.handler.codec.serialization.ObjectEncoderOutputStream.writeObjectOverride(ObjectEncoderOutputStream.java:70) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at java.io.ObjectOutputStream.writeObject(Unknown Source) ~[?:1.8.0_121]
> at org.teiid.net.socket.OioOjbectChannelFactory$OioObjectChannel.write(OioOjbectChannelFactory.java:136) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.teiid.net.socket.SocketServerInstanceImpl.send(SocketServerInstanceImpl.java:213) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at sun.reflect.GeneratedMethodAccessor24.invoke(Unknown Source) ~[?:?]
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[?:1.8.0_121]
> at java.lang.reflect.Method.invoke(Unknown Source) ~[?:1.8.0_121]
> at org.teiid.net.socket.SocketServerConnectionFactory$ShutdownHandler.invoke(SocketServerConnectionFactory.java:98) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at com.sun.proxy.$Proxy21.send(Unknown Source) ~[?:?]
> at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler.invoke(SocketServerInstanceImpl.java:433) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.teiid.net.socket.SocketServerConnection$1.invoke(SocketServerConnection.java:293) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at com.sun.proxy.$Proxy24.closeRequest(Unknown Source) ~[?:?]
> at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:164) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> ... 9 more
> {code}
> Server-side log excerpt, after raising logger levels to Debug:
> {code}
> 2017-12-15 12:00:45.625 [NIO36 ] DEBUG - processing message:MessageHolder: key=550774 contents=Invoke interface org.teiid.client.DQP.executeRequest
> 2017-12-15 12:00:47.730 [ocessorQueue14017479] DEBUG - send message: MessageHolder: key=550774 contents=ResultsMessage rowCount=256 finalRow=-1
> 2017-12-15 12:00:47.737 [NIO36 ] DEBUG - processing message:MessageHolder: key=550776 contents=Invoke interface org.teiid.client.DQP.processCursorRequest
> 2017-12-15 12:00:47.738 [ocessorQueue14017553] DEBUG - send message: MessageHolder: key=550776 contents=ResultsMessage rowCount=2048 finalRow=-1
> 2017-12-15 12:00:47.755 [NIO36 ] DEBUG - processing message:MessageHolder: key=550777 contents=Invoke interface org.teiid.client.DQP.processCursorRequest
> 2017-12-15 12:00:47.756 [ocessorQueue14017554] DEBUG - send message: MessageHolder: key=550777 contents=ResultsMessage rowCount=2048 finalRow=-1
> 2017-12-15 12:00:48.389 [NIO36 ] DEBUG - processing message:MessageHolder: key=550778 contents=Invoke interface org.teiid.client.DQP.processCursorRequest
> 2017-12-15 12:00:48.389 [ocessorQueue14017556] DEBUG - send message: MessageHolder: key=550778 contents=ResultsMessage rowCount=2048 finalRow=-1
> 2017-12-15 12:00:48.825 [NIO36 ] DEBUG - processing message:MessageHolder: key=550779 contents=Invoke interface org.teiid.client.DQP.processCursorRequest
> 2017-12-15 12:00:48.826 [ocessorQueue14017557] DEBUG - send message: MessageHolder: key=550779 contents=ResultsMessage rowCount=2048 finalRow=-1
> 2017-12-15 12:00:48.932 [NIO36 ] DEBUG - processing message:MessageHolder: key=550780 contents=Invoke interface org.teiid.client.DQP.processCursorRequest
> 2017-12-15 12:00:48.933 [ocessorQueue14017558] DEBUG - send message: MessageHolder: key=550780 contents=ResultsMessage rowCount=2048 finalRow=-1
> 2017-12-15 12:02:18.386 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:05:55.327 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:09:29.545 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:13:08.903 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:16:41.864 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:20:16.875 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:23:57.860 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:27:30.273 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:31:07.795 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:34:46.439 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:38:23.325 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:41:59.227 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:45:35.526 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:49:14.088 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:52:46.177 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:56:24.407 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 13:00:03.109 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 13:00:52.143 [NIO36 ] DEBUG - TEIID40114 Unhandled exception, closing client instance: Connection reset by peer
> java.io.IOException: Connection reset by peer
> at sun.nio.ch.FileDispatcherImpl.read0(Native Method)
> at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39)
> at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:223)
> at sun.nio.ch.IOUtil.read(IOUtil.java:192)
> at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:380)
> at io.netty.buffer.UnpooledUnsafeDirectByteBuf.setBytes(UnpooledUnsafeDirectByteBuf.java:447)
> at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:880)
> at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:242)
> at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:119)
> at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:511)
> at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:468)
> at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:382)
> at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:354)
> at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:112)
> at java.lang.Thread.run(Thread.java:745)
> 2017-12-15 13:00:52.143 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 13:03:34.811 [NIO36 ] DEBUG - Channel closed
> {code}
> Legend:
> * 'Channel closed' is logged from org.teiid.transport.SSLAwareChannelHandler class, and its channelInactive method;
> * 'MessageHolder' logs are from org.teiid.net.socket.Message;
> * the log lines that contain rowCount, finalRow, etc. are coming from org.teiid.transport.SocketClientInstance.
> The problem is rarely reproducible, but it happens a few times every day, while running the JMeter tests full day.
> We are also running JMeter in a scenario where the client is referring directly to a serv
--
This message was sent by Atlassian JIRA
(v7.5.0#75005)
6 years, 4 months
- 1
- 0
[JBoss JIRA] (TEIID-5185) JDBC client intermittently hangs when processing multi-batch result sets from server
by Krum Bakalsky (JIRA)
[ https://issues.jboss.org/browse/TEIID-5185?page=com.atlassian.jira.plugin... ]
Krum Bakalsky updated TEIID-5185:
---------------------------------
Description:
We have a server-side application that is powered by Teiid version 9.3.4, and that exposes a Teiid JDBC endpoint to its clients.
A couple of app instances are configured to sit behind a VIP load balancer, that works on the TCP level.
We have been experiencing intermittently following problem, when we run Teiid 9.3.4 client to execute multi-batch queries to the server:
* client successfully fetches few batches from server;
* client hangs and its thread blocks on waiting for the next batch to be delivered on the network;
* after 1 hour client throws exceptions that Socket is closed.
When building up the JDBC connection URL the client refers directly to the server's VIP, and does not list particular service hosts:
jdbc:teiid:<Application>@mm://<VIP's DNS name>:<port>
Client thread's call stack:
{code}
"Thread Group 1-1" #41 prio=6 os_prio=0 tid=0x000000005e03a800 nid=0x17bc runnable [0x00000000623ae000]
java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.socketRead(Unknown Source)
at java.net.SocketInputStream.read(Unknown Source)
at java.net.SocketInputStream.read(Unknown Source)
at java.io.BufferedInputStream.fill(Unknown Source)
at java.io.BufferedInputStream.read(Unknown Source)
- locked <0x00000000f5f32420> (a org.teiid.core.util.AccessibleBufferedInputStream)
at java.io.DataInputStream.readInt(Unknown Source)
at org.teiid.netty.handler.codec.serialization.ObjectDecoderInputStream.readObjectOverride(ObjectDecoderInputStream.java:97)
at java.io.ObjectInputStream.readObject(Unknown Source)
at org.teiid.net.socket.OioOjbectChannelFactory$OioObjectChannel.read(OioOjbectChannelFactory.java:117)
at org.teiid.net.socket.SocketServerInstanceImpl.read(SocketServerInstanceImpl.java:324)
at sun.reflect.GeneratedMethodAccessor22.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
at java.lang.reflect.Method.invoke(Unknown Source)
at org.teiid.net.socket.SocketServerConnectionFactory$ShutdownHandler.invoke(SocketServerConnectionFactory.java:98)
at com.sun.proxy.$Proxy21.read(Unknown Source)
at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler$1.get(SocketServerInstanceImpl.java:427)
at org.teiid.jdbc.ResultSetImpl.getResults(ResultSetImpl.java:449)
at org.teiid.jdbc.ResultSetImpl.requestBatch(ResultSetImpl.java:382)
at org.teiid.jdbc.BatchResults.requestBatchAndWait(BatchResults.java:227)
at org.teiid.jdbc.BatchResults.requestNextBatch(BatchResults.java:142)
at org.teiid.jdbc.BatchResults.hasNext(BatchResults.java:253)
at org.teiid.jdbc.ResultSetImpl.hasNext(ResultSetImpl.java:510)
at org.teiid.jdbc.ResultSetImpl.next(ResultSetImpl.java:259)
at org.apache.commons.dbcp2.DelegatingResultSet.next(DelegatingResultSet.java:191)
at org.apache.commons.dbcp2.DelegatingResultSet.next(DelegatingResultSet.java:191)
at org.apache.jmeter.protocol.jdbc.AbstractJDBCTestElement.getStringFromResultSet(AbstractJDBCTestElement.java:535)
at org.apache.jmeter.protocol.jdbc.AbstractJDBCTestElement.execute(AbstractJDBCTestElement.java:174)
at org.apache.jmeter.protocol.jdbc.sampler.JDBCSampler.sample(JDBCSampler.java:84)
at org.apache.jmeter.threads.JMeterThread.executeSamplePackage(JMeterThread.java:491)
at org.apache.jmeter.threads.JMeterThread.processSampler(JMeterThread.java:425)
at org.apache.jmeter.threads.JMeterThread.run(JMeterThread.java:254)
at java.lang.Thread.run(Unknown Source)
Locked ownable synchronizers:
- None
{code}
Client side exception after 1 hour:
{code}
2017-12-19 13:17:07,160 WARN o.a.j.p.j.AbstractJDBCTestElement: Error closing ResultSet
org.teiid.jdbc.TeiidSQLException: TEIID20013 java.net.SocketException: Socket closed
at org.teiid.jdbc.TeiidSQLException.create(TeiidSQLException.java:135) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.jdbc.TeiidSQLException.create(TeiidSQLException.java:71) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:168) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.apache.commons.dbcp2.DelegatingResultSet.close(DelegatingResultSet.java:170) ~[commons-dbcp2-2.1.1.jar:2.1.1]
at org.apache.commons.dbcp2.DelegatingResultSet.close(DelegatingResultSet.java:170) ~[commons-dbcp2-2.1.1.jar:2.1.1]
at org.apache.jmeter.protocol.jdbc.AbstractJDBCTestElement.close(AbstractJDBCTestElement.java:607) [ApacheJMeter_jdbc.jar:3.2 r1790748]
at org.apache.jmeter.protocol.jdbc.AbstractJDBCTestElement.execute(AbstractJDBCTestElement.java:176) [ApacheJMeter_jdbc.jar:3.2 r1790748]
at org.apache.jmeter.protocol.jdbc.sampler.JDBCSampler.sample(JDBCSampler.java:84) [ApacheJMeter_jdbc.jar:3.2 r1790748]
at org.apache.jmeter.threads.JMeterThread.executeSamplePackage(JMeterThread.java:491) [ApacheJMeter_core.jar:3.2 r1790748]
at org.apache.jmeter.threads.JMeterThread.processSampler(JMeterThread.java:425) [ApacheJMeter_core.jar:3.2 r1790748]
at org.apache.jmeter.threads.JMeterThread.run(JMeterThread.java:254) [ApacheJMeter_core.jar:3.2 r1790748]
at java.lang.Thread.run(Unknown Source) [?:1.8.0_121]
Caused by: org.teiid.core.TeiidComponentException: TEIID20013 java.net.SocketException: Socket closed
at org.teiid.client.util.ExceptionUtil.convertException(ExceptionUtil.java:65) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler.invoke(SocketServerInstanceImpl.java:445) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.net.socket.SocketServerConnection$1.invoke(SocketServerConnection.java:293) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at com.sun.proxy.$Proxy24.closeRequest(Unknown Source) ~[?:?]
at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:164) ~[teiid-9.3.4-jdbc.jar:9.3.4]
... 9 more
Caused by: org.teiid.net.socket.SingleInstanceCommunicationException: TEIID20013 java.net.SocketException: Socket closed
at org.teiid.net.socket.SocketServerInstanceImpl.send(SocketServerInstanceImpl.java:217) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at sun.reflect.GeneratedMethodAccessor24.invoke(Unknown Source) ~[?:?]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[?:1.8.0_121]
at java.lang.reflect.Method.invoke(Unknown Source) ~[?:1.8.0_121]
at org.teiid.net.socket.SocketServerConnectionFactory$ShutdownHandler.invoke(SocketServerConnectionFactory.java:98) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at com.sun.proxy.$Proxy21.send(Unknown Source) ~[?:?]
at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler.invoke(SocketServerInstanceImpl.java:433) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.net.socket.SocketServerConnection$1.invoke(SocketServerConnection.java:293) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at com.sun.proxy.$Proxy24.closeRequest(Unknown Source) ~[?:?]
at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:164) ~[teiid-9.3.4-jdbc.jar:9.3.4]
... 9 more
Caused by: java.util.concurrent.ExecutionException: java.net.SocketException: Socket closed
at org.teiid.client.util.ResultsFuture.convertResult(ResultsFuture.java:104) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.client.util.ResultsFuture.get(ResultsFuture.java:99) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.net.socket.SocketServerInstanceImpl.send(SocketServerInstanceImpl.java:214) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at sun.reflect.GeneratedMethodAccessor24.invoke(Unknown Source) ~[?:?]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[?:1.8.0_121]
at java.lang.reflect.Method.invoke(Unknown Source) ~[?:1.8.0_121]
at org.teiid.net.socket.SocketServerConnectionFactory$ShutdownHandler.invoke(SocketServerConnectionFactory.java:98) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at com.sun.proxy.$Proxy21.send(Unknown Source) ~[?:?]
at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler.invoke(SocketServerInstanceImpl.java:433) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.net.socket.SocketServerConnection$1.invoke(SocketServerConnection.java:293) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at com.sun.proxy.$Proxy24.closeRequest(Unknown Source) ~[?:?]
at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:164) ~[teiid-9.3.4-jdbc.jar:9.3.4]
... 9 more
Caused by: java.net.SocketException: Socket closed
at java.net.SocketOutputStream.socketWrite(Unknown Source) ~[?:1.8.0_121]
at java.net.SocketOutputStream.write(Unknown Source) ~[?:1.8.0_121]
at java.io.DataOutputStream.write(Unknown Source) ~[?:1.8.0_121]
at org.teiid.core.util.MultiArrayOutputStream.writeTo(MultiArrayOutputStream.java:94) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.netty.handler.codec.serialization.ObjectEncoderOutputStream.writeObjectOverride(ObjectEncoderOutputStream.java:70) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at java.io.ObjectOutputStream.writeObject(Unknown Source) ~[?:1.8.0_121]
at org.teiid.net.socket.OioOjbectChannelFactory$OioObjectChannel.write(OioOjbectChannelFactory.java:136) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.net.socket.SocketServerInstanceImpl.send(SocketServerInstanceImpl.java:213) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at sun.reflect.GeneratedMethodAccessor24.invoke(Unknown Source) ~[?:?]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[?:1.8.0_121]
at java.lang.reflect.Method.invoke(Unknown Source) ~[?:1.8.0_121]
at org.teiid.net.socket.SocketServerConnectionFactory$ShutdownHandler.invoke(SocketServerConnectionFactory.java:98) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at com.sun.proxy.$Proxy21.send(Unknown Source) ~[?:?]
at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler.invoke(SocketServerInstanceImpl.java:433) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.net.socket.SocketServerConnection$1.invoke(SocketServerConnection.java:293) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at com.sun.proxy.$Proxy24.closeRequest(Unknown Source) ~[?:?]
at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:164) ~[teiid-9.3.4-jdbc.jar:9.3.4]
... 9 more
{code}
Server-side log excerpt, after raising logger levels to Debug:
{code}
2017-12-15 12:00:45.625 [NIO36 ] DEBUG - processing message:MessageHolder: key=550774 contents=Invoke interface org.teiid.client.DQP.executeRequest
2017-12-15 12:00:47.730 [ocessorQueue14017479] DEBUG - send message: MessageHolder: key=550774 contents=ResultsMessage rowCount=256 finalRow=-1
2017-12-15 12:00:47.737 [NIO36 ] DEBUG - processing message:MessageHolder: key=550776 contents=Invoke interface org.teiid.client.DQP.processCursorRequest
2017-12-15 12:00:47.738 [ocessorQueue14017553] DEBUG - send message: MessageHolder: key=550776 contents=ResultsMessage rowCount=2048 finalRow=-1
2017-12-15 12:00:47.755 [NIO36 ] DEBUG - processing message:MessageHolder: key=550777 contents=Invoke interface org.teiid.client.DQP.processCursorRequest
2017-12-15 12:00:47.756 [ocessorQueue14017554] DEBUG - send message: MessageHolder: key=550777 contents=ResultsMessage rowCount=2048 finalRow=-1
2017-12-15 12:00:48.389 [NIO36 ] DEBUG - processing message:MessageHolder: key=550778 contents=Invoke interface org.teiid.client.DQP.processCursorRequest
2017-12-15 12:00:48.389 [ocessorQueue14017556] DEBUG - send message: MessageHolder: key=550778 contents=ResultsMessage rowCount=2048 finalRow=-1
2017-12-15 12:00:48.825 [NIO36 ] DEBUG - processing message:MessageHolder: key=550779 contents=Invoke interface org.teiid.client.DQP.processCursorRequest
2017-12-15 12:00:48.826 [ocessorQueue14017557] DEBUG - send message: MessageHolder: key=550779 contents=ResultsMessage rowCount=2048 finalRow=-1
2017-12-15 12:00:48.932 [NIO36 ] DEBUG - processing message:MessageHolder: key=550780 contents=Invoke interface org.teiid.client.DQP.processCursorRequest
2017-12-15 12:00:48.933 [ocessorQueue14017558] DEBUG - send message: MessageHolder: key=550780 contents=ResultsMessage rowCount=2048 finalRow=-1
2017-12-15 12:02:18.386 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:05:55.327 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:09:29.545 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:13:08.903 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:16:41.864 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:20:16.875 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:23:57.860 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:27:30.273 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:31:07.795 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:34:46.439 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:38:23.325 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:41:59.227 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:45:35.526 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:49:14.088 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:52:46.177 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:56:24.407 [NIO36 ] DEBUG - Channel closed
2017-12-15 13:00:03.109 [NIO36 ] DEBUG - Channel closed
2017-12-15 13:00:52.143 [NIO36 ] DEBUG - TEIID40114 Unhandled exception, closing client instance: Connection reset by peer
java.io.IOException: Connection reset by peer
at sun.nio.ch.FileDispatcherImpl.read0(Native Method)
at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39)
at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:223)
at sun.nio.ch.IOUtil.read(IOUtil.java:192)
at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:380)
at io.netty.buffer.UnpooledUnsafeDirectByteBuf.setBytes(UnpooledUnsafeDirectByteBuf.java:447)
at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:880)
at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:242)
at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:119)
at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:511)
at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:468)
at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:382)
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:354)
at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:112)
at java.lang.Thread.run(Thread.java:745)
2017-12-15 13:00:52.143 [NIO36 ] DEBUG - Channel closed
2017-12-15 13:03:34.811 [NIO36 ] DEBUG - Channel closed
{code}
Legend:
* 'Channel closed' is logged from org.teiid.transport.SSLAwareChannelHandler class, and its channelInactive method;
* 'MessageHolder' logs are from org.teiid.net.socket.Message;
* the log lines that contain rowCount, finalRow, etc. are coming from org.teiid.transport.SocketClientInstance.
The problem is rarely reproducible, but it happens a few times every day, while running the JMeter tests full day.
W
was:
We have a server-side application that is powered by Teiid version 9.3.4, and that exposes a Teiid JDBC endpoint to its clients.
A couple of app instances are configured to sit behind a VIP load balancer, that works on the TCP level.
We have been experiencing intermittently following problem, when we run Teiid 9.3.4 client to execute multi-batch queries to the server:
* client successfully fetches few batches from server;
* client hangs and its thread blocks on waiting for the next batch to be delivered on the network;
* after 1 hour client throws exceptions that Socket is closed.
Client thread's call stack:
{code}
"Thread Group 1-1" #41 prio=6 os_prio=0 tid=0x000000005e03a800 nid=0x17bc runnable [0x00000000623ae000]
java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.socketRead(Unknown Source)
at java.net.SocketInputStream.read(Unknown Source)
at java.net.SocketInputStream.read(Unknown Source)
at java.io.BufferedInputStream.fill(Unknown Source)
at java.io.BufferedInputStream.read(Unknown Source)
- locked <0x00000000f5f32420> (a org.teiid.core.util.AccessibleBufferedInputStream)
at java.io.DataInputStream.readInt(Unknown Source)
at org.teiid.netty.handler.codec.serialization.ObjectDecoderInputStream.readObjectOverride(ObjectDecoderInputStream.java:97)
at java.io.ObjectInputStream.readObject(Unknown Source)
at org.teiid.net.socket.OioOjbectChannelFactory$OioObjectChannel.read(OioOjbectChannelFactory.java:117)
at org.teiid.net.socket.SocketServerInstanceImpl.read(SocketServerInstanceImpl.java:324)
at sun.reflect.GeneratedMethodAccessor22.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
at java.lang.reflect.Method.invoke(Unknown Source)
at org.teiid.net.socket.SocketServerConnectionFactory$ShutdownHandler.invoke(SocketServerConnectionFactory.java:98)
at com.sun.proxy.$Proxy21.read(Unknown Source)
at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler$1.get(SocketServerInstanceImpl.java:427)
at org.teiid.jdbc.ResultSetImpl.getResults(ResultSetImpl.java:449)
at org.teiid.jdbc.ResultSetImpl.requestBatch(ResultSetImpl.java:382)
at org.teiid.jdbc.BatchResults.requestBatchAndWait(BatchResults.java:227)
at org.teiid.jdbc.BatchResults.requestNextBatch(BatchResults.java:142)
at org.teiid.jdbc.BatchResults.hasNext(BatchResults.java:253)
at org.teiid.jdbc.ResultSetImpl.hasNext(ResultSetImpl.java:510)
at org.teiid.jdbc.ResultSetImpl.next(ResultSetImpl.java:259)
at org.apache.commons.dbcp2.DelegatingResultSet.next(DelegatingResultSet.java:191)
at org.apache.commons.dbcp2.DelegatingResultSet.next(DelegatingResultSet.java:191)
at org.apache.jmeter.protocol.jdbc.AbstractJDBCTestElement.getStringFromResultSet(AbstractJDBCTestElement.java:535)
at org.apache.jmeter.protocol.jdbc.AbstractJDBCTestElement.execute(AbstractJDBCTestElement.java:174)
at org.apache.jmeter.protocol.jdbc.sampler.JDBCSampler.sample(JDBCSampler.java:84)
at org.apache.jmeter.threads.JMeterThread.executeSamplePackage(JMeterThread.java:491)
at org.apache.jmeter.threads.JMeterThread.processSampler(JMeterThread.java:425)
at org.apache.jmeter.threads.JMeterThread.run(JMeterThread.java:254)
at java.lang.Thread.run(Unknown Source)
Locked ownable synchronizers:
- None
{code}
Client side exception after 1 hour:
{code}
2017-12-19 13:17:07,160 WARN o.a.j.p.j.AbstractJDBCTestElement: Error closing ResultSet
org.teiid.jdbc.TeiidSQLException: TEIID20013 java.net.SocketException: Socket closed
at org.teiid.jdbc.TeiidSQLException.create(TeiidSQLException.java:135) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.jdbc.TeiidSQLException.create(TeiidSQLException.java:71) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:168) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.apache.commons.dbcp2.DelegatingResultSet.close(DelegatingResultSet.java:170) ~[commons-dbcp2-2.1.1.jar:2.1.1]
at org.apache.commons.dbcp2.DelegatingResultSet.close(DelegatingResultSet.java:170) ~[commons-dbcp2-2.1.1.jar:2.1.1]
at org.apache.jmeter.protocol.jdbc.AbstractJDBCTestElement.close(AbstractJDBCTestElement.java:607) [ApacheJMeter_jdbc.jar:3.2 r1790748]
at org.apache.jmeter.protocol.jdbc.AbstractJDBCTestElement.execute(AbstractJDBCTestElement.java:176) [ApacheJMeter_jdbc.jar:3.2 r1790748]
at org.apache.jmeter.protocol.jdbc.sampler.JDBCSampler.sample(JDBCSampler.java:84) [ApacheJMeter_jdbc.jar:3.2 r1790748]
at org.apache.jmeter.threads.JMeterThread.executeSamplePackage(JMeterThread.java:491) [ApacheJMeter_core.jar:3.2 r1790748]
at org.apache.jmeter.threads.JMeterThread.processSampler(JMeterThread.java:425) [ApacheJMeter_core.jar:3.2 r1790748]
at org.apache.jmeter.threads.JMeterThread.run(JMeterThread.java:254) [ApacheJMeter_core.jar:3.2 r1790748]
at java.lang.Thread.run(Unknown Source) [?:1.8.0_121]
Caused by: org.teiid.core.TeiidComponentException: TEIID20013 java.net.SocketException: Socket closed
at org.teiid.client.util.ExceptionUtil.convertException(ExceptionUtil.java:65) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler.invoke(SocketServerInstanceImpl.java:445) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.net.socket.SocketServerConnection$1.invoke(SocketServerConnection.java:293) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at com.sun.proxy.$Proxy24.closeRequest(Unknown Source) ~[?:?]
at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:164) ~[teiid-9.3.4-jdbc.jar:9.3.4]
... 9 more
Caused by: org.teiid.net.socket.SingleInstanceCommunicationException: TEIID20013 java.net.SocketException: Socket closed
at org.teiid.net.socket.SocketServerInstanceImpl.send(SocketServerInstanceImpl.java:217) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at sun.reflect.GeneratedMethodAccessor24.invoke(Unknown Source) ~[?:?]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[?:1.8.0_121]
at java.lang.reflect.Method.invoke(Unknown Source) ~[?:1.8.0_121]
at org.teiid.net.socket.SocketServerConnectionFactory$ShutdownHandler.invoke(SocketServerConnectionFactory.java:98) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at com.sun.proxy.$Proxy21.send(Unknown Source) ~[?:?]
at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler.invoke(SocketServerInstanceImpl.java:433) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.net.socket.SocketServerConnection$1.invoke(SocketServerConnection.java:293) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at com.sun.proxy.$Proxy24.closeRequest(Unknown Source) ~[?:?]
at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:164) ~[teiid-9.3.4-jdbc.jar:9.3.4]
... 9 more
Caused by: java.util.concurrent.ExecutionException: java.net.SocketException: Socket closed
at org.teiid.client.util.ResultsFuture.convertResult(ResultsFuture.java:104) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.client.util.ResultsFuture.get(ResultsFuture.java:99) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.net.socket.SocketServerInstanceImpl.send(SocketServerInstanceImpl.java:214) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at sun.reflect.GeneratedMethodAccessor24.invoke(Unknown Source) ~[?:?]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[?:1.8.0_121]
at java.lang.reflect.Method.invoke(Unknown Source) ~[?:1.8.0_121]
at org.teiid.net.socket.SocketServerConnectionFactory$ShutdownHandler.invoke(SocketServerConnectionFactory.java:98) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at com.sun.proxy.$Proxy21.send(Unknown Source) ~[?:?]
at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler.invoke(SocketServerInstanceImpl.java:433) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.net.socket.SocketServerConnection$1.invoke(SocketServerConnection.java:293) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at com.sun.proxy.$Proxy24.closeRequest(Unknown Source) ~[?:?]
at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:164) ~[teiid-9.3.4-jdbc.jar:9.3.4]
... 9 more
Caused by: java.net.SocketException: Socket closed
at java.net.SocketOutputStream.socketWrite(Unknown Source) ~[?:1.8.0_121]
at java.net.SocketOutputStream.write(Unknown Source) ~[?:1.8.0_121]
at java.io.DataOutputStream.write(Unknown Source) ~[?:1.8.0_121]
at org.teiid.core.util.MultiArrayOutputStream.writeTo(MultiArrayOutputStream.java:94) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.netty.handler.codec.serialization.ObjectEncoderOutputStream.writeObjectOverride(ObjectEncoderOutputStream.java:70) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at java.io.ObjectOutputStream.writeObject(Unknown Source) ~[?:1.8.0_121]
at org.teiid.net.socket.OioOjbectChannelFactory$OioObjectChannel.write(OioOjbectChannelFactory.java:136) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.net.socket.SocketServerInstanceImpl.send(SocketServerInstanceImpl.java:213) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at sun.reflect.GeneratedMethodAccessor24.invoke(Unknown Source) ~[?:?]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[?:1.8.0_121]
at java.lang.reflect.Method.invoke(Unknown Source) ~[?:1.8.0_121]
at org.teiid.net.socket.SocketServerConnectionFactory$ShutdownHandler.invoke(SocketServerConnectionFactory.java:98) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at com.sun.proxy.$Proxy21.send(Unknown Source) ~[?:?]
at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler.invoke(SocketServerInstanceImpl.java:433) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.net.socket.SocketServerConnection$1.invoke(SocketServerConnection.java:293) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at com.sun.proxy.$Proxy24.closeRequest(Unknown Source) ~[?:?]
at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:164) ~[teiid-9.3.4-jdbc.jar:9.3.4]
... 9 more
{code}
Server-side log excerpt, after raising logger levels to Debug:
{code}
2017-12-15 12:00:45.625 [NIO36 ] DEBUG - processing message:MessageHolder: key=550774 contents=Invoke interface org.teiid.client.DQP.executeRequest
2017-12-15 12:00:47.730 [ocessorQueue14017479] DEBUG - send message: MessageHolder: key=550774 contents=ResultsMessage rowCount=256 finalRow=-1
2017-12-15 12:00:47.737 [NIO36 ] DEBUG - processing message:MessageHolder: key=550776 contents=Invoke interface org.teiid.client.DQP.processCursorRequest
2017-12-15 12:00:47.738 [ocessorQueue14017553] DEBUG - send message: MessageHolder: key=550776 contents=ResultsMessage rowCount=2048 finalRow=-1
2017-12-15 12:00:47.755 [NIO36 ] DEBUG - processing message:MessageHolder: key=550777 contents=Invoke interface org.teiid.client.DQP.processCursorRequest
2017-12-15 12:00:47.756 [ocessorQueue14017554] DEBUG - send message: MessageHolder: key=550777 contents=ResultsMessage rowCount=2048 finalRow=-1
2017-12-15 12:00:48.389 [NIO36 ] DEBUG - processing message:MessageHolder: key=550778 contents=Invoke interface org.teiid.client.DQP.processCursorRequest
2017-12-15 12:00:48.389 [ocessorQueue14017556] DEBUG - send message: MessageHolder: key=550778 contents=ResultsMessage rowCount=2048 finalRow=-1
2017-12-15 12:00:48.825 [NIO36 ] DEBUG - processing message:MessageHolder: key=550779 contents=Invoke interface org.teiid.client.DQP.processCursorRequest
2017-12-15 12:00:48.826 [ocessorQueue14017557] DEBUG - send message: MessageHolder: key=550779 contents=ResultsMessage rowCount=2048 finalRow=-1
2017-12-15 12:00:48.932 [NIO36 ] DEBUG - processing message:MessageHolder: key=550780 contents=Invoke interface org.teiid.client.DQP.processCursorRequest
2017-12-15 12:00:48.933 [ocessorQueue14017558] DEBUG - send message: MessageHolder: key=550780 contents=ResultsMessage rowCount=2048 finalRow=-1
2017-12-15 12:02:18.386 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:05:55.327 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:09:29.545 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:13:08.903 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:16:41.864 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:20:16.875 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:23:57.860 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:27:30.273 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:31:07.795 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:34:46.439 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:38:23.325 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:41:59.227 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:45:35.526 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:49:14.088 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:52:46.177 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:56:24.407 [NIO36 ] DEBUG - Channel closed
2017-12-15 13:00:03.109 [NIO36 ] DEBUG - Channel closed
2017-12-15 13:00:52.143 [NIO36 ] DEBUG - TEIID40114 Unhandled exception, closing client instance: Connection reset by peer
java.io.IOException: Connection reset by peer
at sun.nio.ch.FileDispatcherImpl.read0(Native Method)
at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39)
at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:223)
at sun.nio.ch.IOUtil.read(IOUtil.java:192)
at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:380)
at io.netty.buffer.UnpooledUnsafeDirectByteBuf.setBytes(UnpooledUnsafeDirectByteBuf.java:447)
at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:880)
at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:242)
at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:119)
at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:511)
at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:468)
at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:382)
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:354)
at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:112)
at java.lang.Thread.run(Thread.java:745)
2017-12-15 13:00:52.143 [NIO36 ] DEBUG - Channel closed
2017-12-15 13:03:34.811 [NIO36 ] DEBUG - Channel closed
{code}
Legend:
* 'Channel closed' is logged from org.teiid.transport.SSLAwareChannelHandler class, and its channelInactive method;
* 'MessageHolder' logs are from org.teiid.net.socket.Message;
* the log lines that contain rowCount, finalRow, etc. are coming from org.teiid.transport.SocketClientInstance.
> JDBC client intermittently hangs when processing multi-batch result sets from server
> ------------------------------------------------------------------------------------
>
> Key: TEIID-5185
> URL: https://issues.jboss.org/browse/TEIID-5185
> Project: Teiid
> Issue Type: Bug
> Components: JDBC Driver, Server
> Affects Versions: 9.3.4
> Environment: JDBC client was run through Apache JMeter, on a 64-bit Windows 7 Enterprise SP1 machine, using 64-bit JDK 8;
> Teiid Server runs on Linux.
> Reporter: Krum Bakalsky
> Assignee: Steven Hawkins
>
> We have a server-side application that is powered by Teiid version 9.3.4, and that exposes a Teiid JDBC endpoint to its clients.
> A couple of app instances are configured to sit behind a VIP load balancer, that works on the TCP level.
> We have been experiencing intermittently following problem, when we run Teiid 9.3.4 client to execute multi-batch queries to the server:
> * client successfully fetches few batches from server;
> * client hangs and its thread blocks on waiting for the next batch to be delivered on the network;
> * after 1 hour client throws exceptions that Socket is closed.
> When building up the JDBC connection URL the client refers directly to the server's VIP, and does not list particular service hosts:
> jdbc:teiid:<Application>@mm://<VIP's DNS name>:<port>
> Client thread's call stack:
> {code}
> "Thread Group 1-1" #41 prio=6 os_prio=0 tid=0x000000005e03a800 nid=0x17bc runnable [0x00000000623ae000]
> java.lang.Thread.State: RUNNABLE
> at java.net.SocketInputStream.socketRead0(Native Method)
> at java.net.SocketInputStream.socketRead(Unknown Source)
> at java.net.SocketInputStream.read(Unknown Source)
> at java.net.SocketInputStream.read(Unknown Source)
> at java.io.BufferedInputStream.fill(Unknown Source)
> at java.io.BufferedInputStream.read(Unknown Source)
> - locked <0x00000000f5f32420> (a org.teiid.core.util.AccessibleBufferedInputStream)
> at java.io.DataInputStream.readInt(Unknown Source)
> at org.teiid.netty.handler.codec.serialization.ObjectDecoderInputStream.readObjectOverride(ObjectDecoderInputStream.java:97)
> at java.io.ObjectInputStream.readObject(Unknown Source)
> at org.teiid.net.socket.OioOjbectChannelFactory$OioObjectChannel.read(OioOjbectChannelFactory.java:117)
> at org.teiid.net.socket.SocketServerInstanceImpl.read(SocketServerInstanceImpl.java:324)
> at sun.reflect.GeneratedMethodAccessor22.invoke(Unknown Source)
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
> at java.lang.reflect.Method.invoke(Unknown Source)
> at org.teiid.net.socket.SocketServerConnectionFactory$ShutdownHandler.invoke(SocketServerConnectionFactory.java:98)
> at com.sun.proxy.$Proxy21.read(Unknown Source)
> at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler$1.get(SocketServerInstanceImpl.java:427)
> at org.teiid.jdbc.ResultSetImpl.getResults(ResultSetImpl.java:449)
> at org.teiid.jdbc.ResultSetImpl.requestBatch(ResultSetImpl.java:382)
> at org.teiid.jdbc.BatchResults.requestBatchAndWait(BatchResults.java:227)
> at org.teiid.jdbc.BatchResults.requestNextBatch(BatchResults.java:142)
> at org.teiid.jdbc.BatchResults.hasNext(BatchResults.java:253)
> at org.teiid.jdbc.ResultSetImpl.hasNext(ResultSetImpl.java:510)
> at org.teiid.jdbc.ResultSetImpl.next(ResultSetImpl.java:259)
> at org.apache.commons.dbcp2.DelegatingResultSet.next(DelegatingResultSet.java:191)
> at org.apache.commons.dbcp2.DelegatingResultSet.next(DelegatingResultSet.java:191)
> at org.apache.jmeter.protocol.jdbc.AbstractJDBCTestElement.getStringFromResultSet(AbstractJDBCTestElement.java:535)
> at org.apache.jmeter.protocol.jdbc.AbstractJDBCTestElement.execute(AbstractJDBCTestElement.java:174)
> at org.apache.jmeter.protocol.jdbc.sampler.JDBCSampler.sample(JDBCSampler.java:84)
> at org.apache.jmeter.threads.JMeterThread.executeSamplePackage(JMeterThread.java:491)
> at org.apache.jmeter.threads.JMeterThread.processSampler(JMeterThread.java:425)
> at org.apache.jmeter.threads.JMeterThread.run(JMeterThread.java:254)
> at java.lang.Thread.run(Unknown Source)
> Locked ownable synchronizers:
> - None
> {code}
> Client side exception after 1 hour:
> {code}
> 2017-12-19 13:17:07,160 WARN o.a.j.p.j.AbstractJDBCTestElement: Error closing ResultSet
> org.teiid.jdbc.TeiidSQLException: TEIID20013 java.net.SocketException: Socket closed
> at org.teiid.jdbc.TeiidSQLException.create(TeiidSQLException.java:135) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.teiid.jdbc.TeiidSQLException.create(TeiidSQLException.java:71) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:168) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.apache.commons.dbcp2.DelegatingResultSet.close(DelegatingResultSet.java:170) ~[commons-dbcp2-2.1.1.jar:2.1.1]
> at org.apache.commons.dbcp2.DelegatingResultSet.close(DelegatingResultSet.java:170) ~[commons-dbcp2-2.1.1.jar:2.1.1]
> at org.apache.jmeter.protocol.jdbc.AbstractJDBCTestElement.close(AbstractJDBCTestElement.java:607) [ApacheJMeter_jdbc.jar:3.2 r1790748]
> at org.apache.jmeter.protocol.jdbc.AbstractJDBCTestElement.execute(AbstractJDBCTestElement.java:176) [ApacheJMeter_jdbc.jar:3.2 r1790748]
> at org.apache.jmeter.protocol.jdbc.sampler.JDBCSampler.sample(JDBCSampler.java:84) [ApacheJMeter_jdbc.jar:3.2 r1790748]
> at org.apache.jmeter.threads.JMeterThread.executeSamplePackage(JMeterThread.java:491) [ApacheJMeter_core.jar:3.2 r1790748]
> at org.apache.jmeter.threads.JMeterThread.processSampler(JMeterThread.java:425) [ApacheJMeter_core.jar:3.2 r1790748]
> at org.apache.jmeter.threads.JMeterThread.run(JMeterThread.java:254) [ApacheJMeter_core.jar:3.2 r1790748]
> at java.lang.Thread.run(Unknown Source) [?:1.8.0_121]
> Caused by: org.teiid.core.TeiidComponentException: TEIID20013 java.net.SocketException: Socket closed
> at org.teiid.client.util.ExceptionUtil.convertException(ExceptionUtil.java:65) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler.invoke(SocketServerInstanceImpl.java:445) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.teiid.net.socket.SocketServerConnection$1.invoke(SocketServerConnection.java:293) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at com.sun.proxy.$Proxy24.closeRequest(Unknown Source) ~[?:?]
> at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:164) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> ... 9 more
> Caused by: org.teiid.net.socket.SingleInstanceCommunicationException: TEIID20013 java.net.SocketException: Socket closed
> at org.teiid.net.socket.SocketServerInstanceImpl.send(SocketServerInstanceImpl.java:217) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at sun.reflect.GeneratedMethodAccessor24.invoke(Unknown Source) ~[?:?]
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[?:1.8.0_121]
> at java.lang.reflect.Method.invoke(Unknown Source) ~[?:1.8.0_121]
> at org.teiid.net.socket.SocketServerConnectionFactory$ShutdownHandler.invoke(SocketServerConnectionFactory.java:98) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at com.sun.proxy.$Proxy21.send(Unknown Source) ~[?:?]
> at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler.invoke(SocketServerInstanceImpl.java:433) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.teiid.net.socket.SocketServerConnection$1.invoke(SocketServerConnection.java:293) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at com.sun.proxy.$Proxy24.closeRequest(Unknown Source) ~[?:?]
> at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:164) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> ... 9 more
> Caused by: java.util.concurrent.ExecutionException: java.net.SocketException: Socket closed
> at org.teiid.client.util.ResultsFuture.convertResult(ResultsFuture.java:104) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.teiid.client.util.ResultsFuture.get(ResultsFuture.java:99) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.teiid.net.socket.SocketServerInstanceImpl.send(SocketServerInstanceImpl.java:214) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at sun.reflect.GeneratedMethodAccessor24.invoke(Unknown Source) ~[?:?]
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[?:1.8.0_121]
> at java.lang.reflect.Method.invoke(Unknown Source) ~[?:1.8.0_121]
> at org.teiid.net.socket.SocketServerConnectionFactory$ShutdownHandler.invoke(SocketServerConnectionFactory.java:98) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at com.sun.proxy.$Proxy21.send(Unknown Source) ~[?:?]
> at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler.invoke(SocketServerInstanceImpl.java:433) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.teiid.net.socket.SocketServerConnection$1.invoke(SocketServerConnection.java:293) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at com.sun.proxy.$Proxy24.closeRequest(Unknown Source) ~[?:?]
> at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:164) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> ... 9 more
> Caused by: java.net.SocketException: Socket closed
> at java.net.SocketOutputStream.socketWrite(Unknown Source) ~[?:1.8.0_121]
> at java.net.SocketOutputStream.write(Unknown Source) ~[?:1.8.0_121]
> at java.io.DataOutputStream.write(Unknown Source) ~[?:1.8.0_121]
> at org.teiid.core.util.MultiArrayOutputStream.writeTo(MultiArrayOutputStream.java:94) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.teiid.netty.handler.codec.serialization.ObjectEncoderOutputStream.writeObjectOverride(ObjectEncoderOutputStream.java:70) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at java.io.ObjectOutputStream.writeObject(Unknown Source) ~[?:1.8.0_121]
> at org.teiid.net.socket.OioOjbectChannelFactory$OioObjectChannel.write(OioOjbectChannelFactory.java:136) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.teiid.net.socket.SocketServerInstanceImpl.send(SocketServerInstanceImpl.java:213) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at sun.reflect.GeneratedMethodAccessor24.invoke(Unknown Source) ~[?:?]
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[?:1.8.0_121]
> at java.lang.reflect.Method.invoke(Unknown Source) ~[?:1.8.0_121]
> at org.teiid.net.socket.SocketServerConnectionFactory$ShutdownHandler.invoke(SocketServerConnectionFactory.java:98) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at com.sun.proxy.$Proxy21.send(Unknown Source) ~[?:?]
> at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler.invoke(SocketServerInstanceImpl.java:433) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.teiid.net.socket.SocketServerConnection$1.invoke(SocketServerConnection.java:293) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at com.sun.proxy.$Proxy24.closeRequest(Unknown Source) ~[?:?]
> at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:164) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> ... 9 more
> {code}
> Server-side log excerpt, after raising logger levels to Debug:
> {code}
> 2017-12-15 12:00:45.625 [NIO36 ] DEBUG - processing message:MessageHolder: key=550774 contents=Invoke interface org.teiid.client.DQP.executeRequest
> 2017-12-15 12:00:47.730 [ocessorQueue14017479] DEBUG - send message: MessageHolder: key=550774 contents=ResultsMessage rowCount=256 finalRow=-1
> 2017-12-15 12:00:47.737 [NIO36 ] DEBUG - processing message:MessageHolder: key=550776 contents=Invoke interface org.teiid.client.DQP.processCursorRequest
> 2017-12-15 12:00:47.738 [ocessorQueue14017553] DEBUG - send message: MessageHolder: key=550776 contents=ResultsMessage rowCount=2048 finalRow=-1
> 2017-12-15 12:00:47.755 [NIO36 ] DEBUG - processing message:MessageHolder: key=550777 contents=Invoke interface org.teiid.client.DQP.processCursorRequest
> 2017-12-15 12:00:47.756 [ocessorQueue14017554] DEBUG - send message: MessageHolder: key=550777 contents=ResultsMessage rowCount=2048 finalRow=-1
> 2017-12-15 12:00:48.389 [NIO36 ] DEBUG - processing message:MessageHolder: key=550778 contents=Invoke interface org.teiid.client.DQP.processCursorRequest
> 2017-12-15 12:00:48.389 [ocessorQueue14017556] DEBUG - send message: MessageHolder: key=550778 contents=ResultsMessage rowCount=2048 finalRow=-1
> 2017-12-15 12:00:48.825 [NIO36 ] DEBUG - processing message:MessageHolder: key=550779 contents=Invoke interface org.teiid.client.DQP.processCursorRequest
> 2017-12-15 12:00:48.826 [ocessorQueue14017557] DEBUG - send message: MessageHolder: key=550779 contents=ResultsMessage rowCount=2048 finalRow=-1
> 2017-12-15 12:00:48.932 [NIO36 ] DEBUG - processing message:MessageHolder: key=550780 contents=Invoke interface org.teiid.client.DQP.processCursorRequest
> 2017-12-15 12:00:48.933 [ocessorQueue14017558] DEBUG - send message: MessageHolder: key=550780 contents=ResultsMessage rowCount=2048 finalRow=-1
> 2017-12-15 12:02:18.386 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:05:55.327 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:09:29.545 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:13:08.903 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:16:41.864 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:20:16.875 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:23:57.860 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:27:30.273 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:31:07.795 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:34:46.439 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:38:23.325 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:41:59.227 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:45:35.526 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:49:14.088 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:52:46.177 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:56:24.407 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 13:00:03.109 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 13:00:52.143 [NIO36 ] DEBUG - TEIID40114 Unhandled exception, closing client instance: Connection reset by peer
> java.io.IOException: Connection reset by peer
> at sun.nio.ch.FileDispatcherImpl.read0(Native Method)
> at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39)
> at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:223)
> at sun.nio.ch.IOUtil.read(IOUtil.java:192)
> at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:380)
> at io.netty.buffer.UnpooledUnsafeDirectByteBuf.setBytes(UnpooledUnsafeDirectByteBuf.java:447)
> at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:880)
> at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:242)
> at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:119)
> at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:511)
> at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:468)
> at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:382)
> at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:354)
> at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:112)
> at java.lang.Thread.run(Thread.java:745)
> 2017-12-15 13:00:52.143 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 13:03:34.811 [NIO36 ] DEBUG - Channel closed
> {code}
> Legend:
> * 'Channel closed' is logged from org.teiid.transport.SSLAwareChannelHandler class, and its channelInactive method;
> * 'MessageHolder' logs are from org.teiid.net.socket.Message;
> * the log lines that contain rowCount, finalRow, etc. are coming from org.teiid.transport.SocketClientInstance.
> The problem is rarely reproducible, but it happens a few times every day, while running the JMeter tests full day.
> W
--
This message was sent by Atlassian JIRA
(v7.5.0#75005)
6 years, 4 months
- 1
- 0
[JBoss JIRA] (TEIID-5185) JDBC client intermittently hangs when processing multi-batch result sets from server
by Krum Bakalsky (JIRA)
[ https://issues.jboss.org/browse/TEIID-5185?page=com.atlassian.jira.plugin... ]
Krum Bakalsky updated TEIID-5185:
---------------------------------
Description:
We have a server-side application that is powered by Teiid version 9.3.4, and that exposes a Teiid JDBC endpoint to its clients.
A couple of app instances are configured to sit behind a VIP load balancer, that works on the TCP level.
We have been experiencing intermittently following problem, when we run Teiid 9.3.4 client to execute multi-batch queries to the server:
* client successfully fetches few batches from server;
* client hangs and its thread blocks on waiting for the next batch to be delivered on the network;
* after 1 hour client throws exceptions that Socket is closed.
Client thread's call stack:
{code}
"Thread Group 1-1" #41 prio=6 os_prio=0 tid=0x000000005e03a800 nid=0x17bc runnable [0x00000000623ae000]
java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.socketRead(Unknown Source)
at java.net.SocketInputStream.read(Unknown Source)
at java.net.SocketInputStream.read(Unknown Source)
at java.io.BufferedInputStream.fill(Unknown Source)
at java.io.BufferedInputStream.read(Unknown Source)
- locked <0x00000000f5f32420> (a org.teiid.core.util.AccessibleBufferedInputStream)
at java.io.DataInputStream.readInt(Unknown Source)
at org.teiid.netty.handler.codec.serialization.ObjectDecoderInputStream.readObjectOverride(ObjectDecoderInputStream.java:97)
at java.io.ObjectInputStream.readObject(Unknown Source)
at org.teiid.net.socket.OioOjbectChannelFactory$OioObjectChannel.read(OioOjbectChannelFactory.java:117)
at org.teiid.net.socket.SocketServerInstanceImpl.read(SocketServerInstanceImpl.java:324)
at sun.reflect.GeneratedMethodAccessor22.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
at java.lang.reflect.Method.invoke(Unknown Source)
at org.teiid.net.socket.SocketServerConnectionFactory$ShutdownHandler.invoke(SocketServerConnectionFactory.java:98)
at com.sun.proxy.$Proxy21.read(Unknown Source)
at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler$1.get(SocketServerInstanceImpl.java:427)
at org.teiid.jdbc.ResultSetImpl.getResults(ResultSetImpl.java:449)
at org.teiid.jdbc.ResultSetImpl.requestBatch(ResultSetImpl.java:382)
at org.teiid.jdbc.BatchResults.requestBatchAndWait(BatchResults.java:227)
at org.teiid.jdbc.BatchResults.requestNextBatch(BatchResults.java:142)
at org.teiid.jdbc.BatchResults.hasNext(BatchResults.java:253)
at org.teiid.jdbc.ResultSetImpl.hasNext(ResultSetImpl.java:510)
at org.teiid.jdbc.ResultSetImpl.next(ResultSetImpl.java:259)
at org.apache.commons.dbcp2.DelegatingResultSet.next(DelegatingResultSet.java:191)
at org.apache.commons.dbcp2.DelegatingResultSet.next(DelegatingResultSet.java:191)
at org.apache.jmeter.protocol.jdbc.AbstractJDBCTestElement.getStringFromResultSet(AbstractJDBCTestElement.java:535)
at org.apache.jmeter.protocol.jdbc.AbstractJDBCTestElement.execute(AbstractJDBCTestElement.java:174)
at org.apache.jmeter.protocol.jdbc.sampler.JDBCSampler.sample(JDBCSampler.java:84)
at org.apache.jmeter.threads.JMeterThread.executeSamplePackage(JMeterThread.java:491)
at org.apache.jmeter.threads.JMeterThread.processSampler(JMeterThread.java:425)
at org.apache.jmeter.threads.JMeterThread.run(JMeterThread.java:254)
at java.lang.Thread.run(Unknown Source)
Locked ownable synchronizers:
- None
{code}
Client side exception after 1 hour:
{code}
2017-12-19 13:17:07,160 WARN o.a.j.p.j.AbstractJDBCTestElement: Error closing ResultSet
org.teiid.jdbc.TeiidSQLException: TEIID20013 java.net.SocketException: Socket closed
at org.teiid.jdbc.TeiidSQLException.create(TeiidSQLException.java:135) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.jdbc.TeiidSQLException.create(TeiidSQLException.java:71) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:168) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.apache.commons.dbcp2.DelegatingResultSet.close(DelegatingResultSet.java:170) ~[commons-dbcp2-2.1.1.jar:2.1.1]
at org.apache.commons.dbcp2.DelegatingResultSet.close(DelegatingResultSet.java:170) ~[commons-dbcp2-2.1.1.jar:2.1.1]
at org.apache.jmeter.protocol.jdbc.AbstractJDBCTestElement.close(AbstractJDBCTestElement.java:607) [ApacheJMeter_jdbc.jar:3.2 r1790748]
at org.apache.jmeter.protocol.jdbc.AbstractJDBCTestElement.execute(AbstractJDBCTestElement.java:176) [ApacheJMeter_jdbc.jar:3.2 r1790748]
at org.apache.jmeter.protocol.jdbc.sampler.JDBCSampler.sample(JDBCSampler.java:84) [ApacheJMeter_jdbc.jar:3.2 r1790748]
at org.apache.jmeter.threads.JMeterThread.executeSamplePackage(JMeterThread.java:491) [ApacheJMeter_core.jar:3.2 r1790748]
at org.apache.jmeter.threads.JMeterThread.processSampler(JMeterThread.java:425) [ApacheJMeter_core.jar:3.2 r1790748]
at org.apache.jmeter.threads.JMeterThread.run(JMeterThread.java:254) [ApacheJMeter_core.jar:3.2 r1790748]
at java.lang.Thread.run(Unknown Source) [?:1.8.0_121]
Caused by: org.teiid.core.TeiidComponentException: TEIID20013 java.net.SocketException: Socket closed
at org.teiid.client.util.ExceptionUtil.convertException(ExceptionUtil.java:65) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler.invoke(SocketServerInstanceImpl.java:445) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.net.socket.SocketServerConnection$1.invoke(SocketServerConnection.java:293) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at com.sun.proxy.$Proxy24.closeRequest(Unknown Source) ~[?:?]
at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:164) ~[teiid-9.3.4-jdbc.jar:9.3.4]
... 9 more
Caused by: org.teiid.net.socket.SingleInstanceCommunicationException: TEIID20013 java.net.SocketException: Socket closed
at org.teiid.net.socket.SocketServerInstanceImpl.send(SocketServerInstanceImpl.java:217) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at sun.reflect.GeneratedMethodAccessor24.invoke(Unknown Source) ~[?:?]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[?:1.8.0_121]
at java.lang.reflect.Method.invoke(Unknown Source) ~[?:1.8.0_121]
at org.teiid.net.socket.SocketServerConnectionFactory$ShutdownHandler.invoke(SocketServerConnectionFactory.java:98) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at com.sun.proxy.$Proxy21.send(Unknown Source) ~[?:?]
at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler.invoke(SocketServerInstanceImpl.java:433) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.net.socket.SocketServerConnection$1.invoke(SocketServerConnection.java:293) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at com.sun.proxy.$Proxy24.closeRequest(Unknown Source) ~[?:?]
at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:164) ~[teiid-9.3.4-jdbc.jar:9.3.4]
... 9 more
Caused by: java.util.concurrent.ExecutionException: java.net.SocketException: Socket closed
at org.teiid.client.util.ResultsFuture.convertResult(ResultsFuture.java:104) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.client.util.ResultsFuture.get(ResultsFuture.java:99) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.net.socket.SocketServerInstanceImpl.send(SocketServerInstanceImpl.java:214) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at sun.reflect.GeneratedMethodAccessor24.invoke(Unknown Source) ~[?:?]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[?:1.8.0_121]
at java.lang.reflect.Method.invoke(Unknown Source) ~[?:1.8.0_121]
at org.teiid.net.socket.SocketServerConnectionFactory$ShutdownHandler.invoke(SocketServerConnectionFactory.java:98) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at com.sun.proxy.$Proxy21.send(Unknown Source) ~[?:?]
at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler.invoke(SocketServerInstanceImpl.java:433) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.net.socket.SocketServerConnection$1.invoke(SocketServerConnection.java:293) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at com.sun.proxy.$Proxy24.closeRequest(Unknown Source) ~[?:?]
at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:164) ~[teiid-9.3.4-jdbc.jar:9.3.4]
... 9 more
Caused by: java.net.SocketException: Socket closed
at java.net.SocketOutputStream.socketWrite(Unknown Source) ~[?:1.8.0_121]
at java.net.SocketOutputStream.write(Unknown Source) ~[?:1.8.0_121]
at java.io.DataOutputStream.write(Unknown Source) ~[?:1.8.0_121]
at org.teiid.core.util.MultiArrayOutputStream.writeTo(MultiArrayOutputStream.java:94) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.netty.handler.codec.serialization.ObjectEncoderOutputStream.writeObjectOverride(ObjectEncoderOutputStream.java:70) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at java.io.ObjectOutputStream.writeObject(Unknown Source) ~[?:1.8.0_121]
at org.teiid.net.socket.OioOjbectChannelFactory$OioObjectChannel.write(OioOjbectChannelFactory.java:136) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.net.socket.SocketServerInstanceImpl.send(SocketServerInstanceImpl.java:213) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at sun.reflect.GeneratedMethodAccessor24.invoke(Unknown Source) ~[?:?]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[?:1.8.0_121]
at java.lang.reflect.Method.invoke(Unknown Source) ~[?:1.8.0_121]
at org.teiid.net.socket.SocketServerConnectionFactory$ShutdownHandler.invoke(SocketServerConnectionFactory.java:98) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at com.sun.proxy.$Proxy21.send(Unknown Source) ~[?:?]
at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler.invoke(SocketServerInstanceImpl.java:433) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.net.socket.SocketServerConnection$1.invoke(SocketServerConnection.java:293) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at com.sun.proxy.$Proxy24.closeRequest(Unknown Source) ~[?:?]
at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:164) ~[teiid-9.3.4-jdbc.jar:9.3.4]
... 9 more
{code}
Server-side log excerpt, after raising logger levels to Debug:
{code}
2017-12-15 12:00:45.625 [NIO36 ] DEBUG - processing message:MessageHolder: key=550774 contents=Invoke interface org.teiid.client.DQP.executeRequest
2017-12-15 12:00:47.730 [ocessorQueue14017479] DEBUG - send message: MessageHolder: key=550774 contents=ResultsMessage rowCount=256 finalRow=-1
2017-12-15 12:00:47.737 [NIO36 ] DEBUG - processing message:MessageHolder: key=550776 contents=Invoke interface org.teiid.client.DQP.processCursorRequest
2017-12-15 12:00:47.738 [ocessorQueue14017553] DEBUG - send message: MessageHolder: key=550776 contents=ResultsMessage rowCount=2048 finalRow=-1
2017-12-15 12:00:47.755 [NIO36 ] DEBUG - processing message:MessageHolder: key=550777 contents=Invoke interface org.teiid.client.DQP.processCursorRequest
2017-12-15 12:00:47.756 [ocessorQueue14017554] DEBUG - send message: MessageHolder: key=550777 contents=ResultsMessage rowCount=2048 finalRow=-1
2017-12-15 12:00:48.389 [NIO36 ] DEBUG - processing message:MessageHolder: key=550778 contents=Invoke interface org.teiid.client.DQP.processCursorRequest
2017-12-15 12:00:48.389 [ocessorQueue14017556] DEBUG - send message: MessageHolder: key=550778 contents=ResultsMessage rowCount=2048 finalRow=-1
2017-12-15 12:00:48.825 [NIO36 ] DEBUG - processing message:MessageHolder: key=550779 contents=Invoke interface org.teiid.client.DQP.processCursorRequest
2017-12-15 12:00:48.826 [ocessorQueue14017557] DEBUG - send message: MessageHolder: key=550779 contents=ResultsMessage rowCount=2048 finalRow=-1
2017-12-15 12:00:48.932 [NIO36 ] DEBUG - processing message:MessageHolder: key=550780 contents=Invoke interface org.teiid.client.DQP.processCursorRequest
2017-12-15 12:00:48.933 [ocessorQueue14017558] DEBUG - send message: MessageHolder: key=550780 contents=ResultsMessage rowCount=2048 finalRow=-1
2017-12-15 12:02:18.386 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:05:55.327 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:09:29.545 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:13:08.903 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:16:41.864 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:20:16.875 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:23:57.860 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:27:30.273 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:31:07.795 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:34:46.439 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:38:23.325 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:41:59.227 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:45:35.526 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:49:14.088 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:52:46.177 [NIO36 ] DEBUG - Channel closed
2017-12-15 12:56:24.407 [NIO36 ] DEBUG - Channel closed
2017-12-15 13:00:03.109 [NIO36 ] DEBUG - Channel closed
2017-12-15 13:00:52.143 [NIO36 ] DEBUG - TEIID40114 Unhandled exception, closing client instance: Connection reset by peer
java.io.IOException: Connection reset by peer
at sun.nio.ch.FileDispatcherImpl.read0(Native Method)
at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39)
at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:223)
at sun.nio.ch.IOUtil.read(IOUtil.java:192)
at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:380)
at io.netty.buffer.UnpooledUnsafeDirectByteBuf.setBytes(UnpooledUnsafeDirectByteBuf.java:447)
at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:880)
at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:242)
at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:119)
at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:511)
at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:468)
at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:382)
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:354)
at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:112)
at java.lang.Thread.run(Thread.java:745)
2017-12-15 13:00:52.143 [NIO36 ] DEBUG - Channel closed
2017-12-15 13:03:34.811 [NIO36 ] DEBUG - Channel closed
{code}
Legend:
* 'Channel closed' is logged from org.teiid.transport.SSLAwareChannelHandler class, and its channelInactive method;
* 'MessageHolder' logs are from org.teiid.net.socket.Message;
* the log lines that contain rowCount, finalRow, etc. are coming from org.teiid.transport.SocketClientInstance.
was:
We have a server-side application that is powered by Teiid version 9.3.4, and that exposes a Teiid JDBC endpoint to its clients.
A couple of app instances are configured to sit behind a VIP load balancer, that works on the TCP level.
We have been experiencing intermittently following problem, when we run Teiid 9.3.4 client to execute multi-batch queries to the server:
* client successfully fetches few batches from server;
* client hangs and its thread blocks on waiting for the next batch to be delivered on the network;
* after 1 hour client throws exceptions that Socket is closed.
Client thread's call stack:
{code}
"Thread Group 1-1" #41 prio=6 os_prio=0 tid=0x000000005e03a800 nid=0x17bc runnable [0x00000000623ae000]
java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.socketRead(Unknown Source)
at java.net.SocketInputStream.read(Unknown Source)
at java.net.SocketInputStream.read(Unknown Source)
at java.io.BufferedInputStream.fill(Unknown Source)
at java.io.BufferedInputStream.read(Unknown Source)
- locked <0x00000000f5f32420> (a org.teiid.core.util.AccessibleBufferedInputStream)
at java.io.DataInputStream.readInt(Unknown Source)
at org.teiid.netty.handler.codec.serialization.ObjectDecoderInputStream.readObjectOverride(ObjectDecoderInputStream.java:97)
at java.io.ObjectInputStream.readObject(Unknown Source)
at org.teiid.net.socket.OioOjbectChannelFactory$OioObjectChannel.read(OioOjbectChannelFactory.java:117)
at org.teiid.net.socket.SocketServerInstanceImpl.read(SocketServerInstanceImpl.java:324)
at sun.reflect.GeneratedMethodAccessor22.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
at java.lang.reflect.Method.invoke(Unknown Source)
at org.teiid.net.socket.SocketServerConnectionFactory$ShutdownHandler.invoke(SocketServerConnectionFactory.java:98)
at com.sun.proxy.$Proxy21.read(Unknown Source)
at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler$1.get(SocketServerInstanceImpl.java:427)
at org.teiid.jdbc.ResultSetImpl.getResults(ResultSetImpl.java:449)
at org.teiid.jdbc.ResultSetImpl.requestBatch(ResultSetImpl.java:382)
at org.teiid.jdbc.BatchResults.requestBatchAndWait(BatchResults.java:227)
at org.teiid.jdbc.BatchResults.requestNextBatch(BatchResults.java:142)
at org.teiid.jdbc.BatchResults.hasNext(BatchResults.java:253)
at org.teiid.jdbc.ResultSetImpl.hasNext(ResultSetImpl.java:510)
at org.teiid.jdbc.ResultSetImpl.next(ResultSetImpl.java:259)
at org.apache.commons.dbcp2.DelegatingResultSet.next(DelegatingResultSet.java:191)
at org.apache.commons.dbcp2.DelegatingResultSet.next(DelegatingResultSet.java:191)
at org.apache.jmeter.protocol.jdbc.AbstractJDBCTestElement.getStringFromResultSet(AbstractJDBCTestElement.java:535)
at org.apache.jmeter.protocol.jdbc.AbstractJDBCTestElement.execute(AbstractJDBCTestElement.java:174)
at org.apache.jmeter.protocol.jdbc.sampler.JDBCSampler.sample(JDBCSampler.java:84)
at org.apache.jmeter.threads.JMeterThread.executeSamplePackage(JMeterThread.java:491)
at org.apache.jmeter.threads.JMeterThread.processSampler(JMeterThread.java:425)
at org.apache.jmeter.threads.JMeterThread.run(JMeterThread.java:254)
at java.lang.Thread.run(Unknown Source)
Locked ownable synchronizers:
- None
{code}
Client side exception after 1 hour:
{code}
2017-12-19 13:17:07,160 WARN o.a.j.p.j.AbstractJDBCTestElement: Error closing ResultSet
org.teiid.jdbc.TeiidSQLException: TEIID20013 java.net.SocketException: Socket closed
at org.teiid.jdbc.TeiidSQLException.create(TeiidSQLException.java:135) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.jdbc.TeiidSQLException.create(TeiidSQLException.java:71) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:168) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.apache.commons.dbcp2.DelegatingResultSet.close(DelegatingResultSet.java:170) ~[commons-dbcp2-2.1.1.jar:2.1.1]
at org.apache.commons.dbcp2.DelegatingResultSet.close(DelegatingResultSet.java:170) ~[commons-dbcp2-2.1.1.jar:2.1.1]
at org.apache.jmeter.protocol.jdbc.AbstractJDBCTestElement.close(AbstractJDBCTestElement.java:607) [ApacheJMeter_jdbc.jar:3.2 r1790748]
at org.apache.jmeter.protocol.jdbc.AbstractJDBCTestElement.execute(AbstractJDBCTestElement.java:176) [ApacheJMeter_jdbc.jar:3.2 r1790748]
at org.apache.jmeter.protocol.jdbc.sampler.JDBCSampler.sample(JDBCSampler.java:84) [ApacheJMeter_jdbc.jar:3.2 r1790748]
at org.apache.jmeter.threads.JMeterThread.executeSamplePackage(JMeterThread.java:491) [ApacheJMeter_core.jar:3.2 r1790748]
at org.apache.jmeter.threads.JMeterThread.processSampler(JMeterThread.java:425) [ApacheJMeter_core.jar:3.2 r1790748]
at org.apache.jmeter.threads.JMeterThread.run(JMeterThread.java:254) [ApacheJMeter_core.jar:3.2 r1790748]
at java.lang.Thread.run(Unknown Source) [?:1.8.0_121]
Caused by: org.teiid.core.TeiidComponentException: TEIID20013 java.net.SocketException: Socket closed
at org.teiid.client.util.ExceptionUtil.convertException(ExceptionUtil.java:65) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler.invoke(SocketServerInstanceImpl.java:445) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.net.socket.SocketServerConnection$1.invoke(SocketServerConnection.java:293) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at com.sun.proxy.$Proxy24.closeRequest(Unknown Source) ~[?:?]
at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:164) ~[teiid-9.3.4-jdbc.jar:9.3.4]
... 9 more
Caused by: org.teiid.net.socket.SingleInstanceCommunicationException: TEIID20013 java.net.SocketException: Socket closed
at org.teiid.net.socket.SocketServerInstanceImpl.send(SocketServerInstanceImpl.java:217) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at sun.reflect.GeneratedMethodAccessor24.invoke(Unknown Source) ~[?:?]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[?:1.8.0_121]
at java.lang.reflect.Method.invoke(Unknown Source) ~[?:1.8.0_121]
at org.teiid.net.socket.SocketServerConnectionFactory$ShutdownHandler.invoke(SocketServerConnectionFactory.java:98) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at com.sun.proxy.$Proxy21.send(Unknown Source) ~[?:?]
at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler.invoke(SocketServerInstanceImpl.java:433) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.net.socket.SocketServerConnection$1.invoke(SocketServerConnection.java:293) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at com.sun.proxy.$Proxy24.closeRequest(Unknown Source) ~[?:?]
at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:164) ~[teiid-9.3.4-jdbc.jar:9.3.4]
... 9 more
Caused by: java.util.concurrent.ExecutionException: java.net.SocketException: Socket closed
at org.teiid.client.util.ResultsFuture.convertResult(ResultsFuture.java:104) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.client.util.ResultsFuture.get(ResultsFuture.java:99) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.net.socket.SocketServerInstanceImpl.send(SocketServerInstanceImpl.java:214) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at sun.reflect.GeneratedMethodAccessor24.invoke(Unknown Source) ~[?:?]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[?:1.8.0_121]
at java.lang.reflect.Method.invoke(Unknown Source) ~[?:1.8.0_121]
at org.teiid.net.socket.SocketServerConnectionFactory$ShutdownHandler.invoke(SocketServerConnectionFactory.java:98) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at com.sun.proxy.$Proxy21.send(Unknown Source) ~[?:?]
at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler.invoke(SocketServerInstanceImpl.java:433) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.net.socket.SocketServerConnection$1.invoke(SocketServerConnection.java:293) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at com.sun.proxy.$Proxy24.closeRequest(Unknown Source) ~[?:?]
at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:164) ~[teiid-9.3.4-jdbc.jar:9.3.4]
... 9 more
Caused by: java.net.SocketException: Socket closed
at java.net.SocketOutputStream.socketWrite(Unknown Source) ~[?:1.8.0_121]
at java.net.SocketOutputStream.write(Unknown Source) ~[?:1.8.0_121]
at java.io.DataOutputStream.write(Unknown Source) ~[?:1.8.0_121]
at org.teiid.core.util.MultiArrayOutputStream.writeTo(MultiArrayOutputStream.java:94) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.netty.handler.codec.serialization.ObjectEncoderOutputStream.writeObjectOverride(ObjectEncoderOutputStream.java:70) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at java.io.ObjectOutputStream.writeObject(Unknown Source) ~[?:1.8.0_121]
at org.teiid.net.socket.OioOjbectChannelFactory$OioObjectChannel.write(OioOjbectChannelFactory.java:136) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.net.socket.SocketServerInstanceImpl.send(SocketServerInstanceImpl.java:213) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at sun.reflect.GeneratedMethodAccessor24.invoke(Unknown Source) ~[?:?]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[?:1.8.0_121]
at java.lang.reflect.Method.invoke(Unknown Source) ~[?:1.8.0_121]
at org.teiid.net.socket.SocketServerConnectionFactory$ShutdownHandler.invoke(SocketServerConnectionFactory.java:98) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at com.sun.proxy.$Proxy21.send(Unknown Source) ~[?:?]
at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler.invoke(SocketServerInstanceImpl.java:433) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at org.teiid.net.socket.SocketServerConnection$1.invoke(SocketServerConnection.java:293) ~[teiid-9.3.4-jdbc.jar:9.3.4]
at com.sun.proxy.$Proxy24.closeRequest(Unknown Source) ~[?:?]
at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:164) ~[teiid-9.3.4-jdbc.jar:9.3.4]
... 9 more
{code}
> JDBC client intermittently hangs when processing multi-batch result sets from server
> ------------------------------------------------------------------------------------
>
> Key: TEIID-5185
> URL: https://issues.jboss.org/browse/TEIID-5185
> Project: Teiid
> Issue Type: Bug
> Components: JDBC Driver, Server
> Affects Versions: 9.3.4
> Environment: JDBC client was run through Apache JMeter, on a 64-bit Windows 7 Enterprise SP1 machine, using 64-bit JDK 8;
> Teiid Server runs on Linux.
> Reporter: Krum Bakalsky
> Assignee: Steven Hawkins
>
> We have a server-side application that is powered by Teiid version 9.3.4, and that exposes a Teiid JDBC endpoint to its clients.
> A couple of app instances are configured to sit behind a VIP load balancer, that works on the TCP level.
> We have been experiencing intermittently following problem, when we run Teiid 9.3.4 client to execute multi-batch queries to the server:
> * client successfully fetches few batches from server;
> * client hangs and its thread blocks on waiting for the next batch to be delivered on the network;
> * after 1 hour client throws exceptions that Socket is closed.
> Client thread's call stack:
> {code}
> "Thread Group 1-1" #41 prio=6 os_prio=0 tid=0x000000005e03a800 nid=0x17bc runnable [0x00000000623ae000]
> java.lang.Thread.State: RUNNABLE
> at java.net.SocketInputStream.socketRead0(Native Method)
> at java.net.SocketInputStream.socketRead(Unknown Source)
> at java.net.SocketInputStream.read(Unknown Source)
> at java.net.SocketInputStream.read(Unknown Source)
> at java.io.BufferedInputStream.fill(Unknown Source)
> at java.io.BufferedInputStream.read(Unknown Source)
> - locked <0x00000000f5f32420> (a org.teiid.core.util.AccessibleBufferedInputStream)
> at java.io.DataInputStream.readInt(Unknown Source)
> at org.teiid.netty.handler.codec.serialization.ObjectDecoderInputStream.readObjectOverride(ObjectDecoderInputStream.java:97)
> at java.io.ObjectInputStream.readObject(Unknown Source)
> at org.teiid.net.socket.OioOjbectChannelFactory$OioObjectChannel.read(OioOjbectChannelFactory.java:117)
> at org.teiid.net.socket.SocketServerInstanceImpl.read(SocketServerInstanceImpl.java:324)
> at sun.reflect.GeneratedMethodAccessor22.invoke(Unknown Source)
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
> at java.lang.reflect.Method.invoke(Unknown Source)
> at org.teiid.net.socket.SocketServerConnectionFactory$ShutdownHandler.invoke(SocketServerConnectionFactory.java:98)
> at com.sun.proxy.$Proxy21.read(Unknown Source)
> at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler$1.get(SocketServerInstanceImpl.java:427)
> at org.teiid.jdbc.ResultSetImpl.getResults(ResultSetImpl.java:449)
> at org.teiid.jdbc.ResultSetImpl.requestBatch(ResultSetImpl.java:382)
> at org.teiid.jdbc.BatchResults.requestBatchAndWait(BatchResults.java:227)
> at org.teiid.jdbc.BatchResults.requestNextBatch(BatchResults.java:142)
> at org.teiid.jdbc.BatchResults.hasNext(BatchResults.java:253)
> at org.teiid.jdbc.ResultSetImpl.hasNext(ResultSetImpl.java:510)
> at org.teiid.jdbc.ResultSetImpl.next(ResultSetImpl.java:259)
> at org.apache.commons.dbcp2.DelegatingResultSet.next(DelegatingResultSet.java:191)
> at org.apache.commons.dbcp2.DelegatingResultSet.next(DelegatingResultSet.java:191)
> at org.apache.jmeter.protocol.jdbc.AbstractJDBCTestElement.getStringFromResultSet(AbstractJDBCTestElement.java:535)
> at org.apache.jmeter.protocol.jdbc.AbstractJDBCTestElement.execute(AbstractJDBCTestElement.java:174)
> at org.apache.jmeter.protocol.jdbc.sampler.JDBCSampler.sample(JDBCSampler.java:84)
> at org.apache.jmeter.threads.JMeterThread.executeSamplePackage(JMeterThread.java:491)
> at org.apache.jmeter.threads.JMeterThread.processSampler(JMeterThread.java:425)
> at org.apache.jmeter.threads.JMeterThread.run(JMeterThread.java:254)
> at java.lang.Thread.run(Unknown Source)
> Locked ownable synchronizers:
> - None
> {code}
> Client side exception after 1 hour:
> {code}
> 2017-12-19 13:17:07,160 WARN o.a.j.p.j.AbstractJDBCTestElement: Error closing ResultSet
> org.teiid.jdbc.TeiidSQLException: TEIID20013 java.net.SocketException: Socket closed
> at org.teiid.jdbc.TeiidSQLException.create(TeiidSQLException.java:135) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.teiid.jdbc.TeiidSQLException.create(TeiidSQLException.java:71) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:168) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.apache.commons.dbcp2.DelegatingResultSet.close(DelegatingResultSet.java:170) ~[commons-dbcp2-2.1.1.jar:2.1.1]
> at org.apache.commons.dbcp2.DelegatingResultSet.close(DelegatingResultSet.java:170) ~[commons-dbcp2-2.1.1.jar:2.1.1]
> at org.apache.jmeter.protocol.jdbc.AbstractJDBCTestElement.close(AbstractJDBCTestElement.java:607) [ApacheJMeter_jdbc.jar:3.2 r1790748]
> at org.apache.jmeter.protocol.jdbc.AbstractJDBCTestElement.execute(AbstractJDBCTestElement.java:176) [ApacheJMeter_jdbc.jar:3.2 r1790748]
> at org.apache.jmeter.protocol.jdbc.sampler.JDBCSampler.sample(JDBCSampler.java:84) [ApacheJMeter_jdbc.jar:3.2 r1790748]
> at org.apache.jmeter.threads.JMeterThread.executeSamplePackage(JMeterThread.java:491) [ApacheJMeter_core.jar:3.2 r1790748]
> at org.apache.jmeter.threads.JMeterThread.processSampler(JMeterThread.java:425) [ApacheJMeter_core.jar:3.2 r1790748]
> at org.apache.jmeter.threads.JMeterThread.run(JMeterThread.java:254) [ApacheJMeter_core.jar:3.2 r1790748]
> at java.lang.Thread.run(Unknown Source) [?:1.8.0_121]
> Caused by: org.teiid.core.TeiidComponentException: TEIID20013 java.net.SocketException: Socket closed
> at org.teiid.client.util.ExceptionUtil.convertException(ExceptionUtil.java:65) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler.invoke(SocketServerInstanceImpl.java:445) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.teiid.net.socket.SocketServerConnection$1.invoke(SocketServerConnection.java:293) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at com.sun.proxy.$Proxy24.closeRequest(Unknown Source) ~[?:?]
> at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:164) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> ... 9 more
> Caused by: org.teiid.net.socket.SingleInstanceCommunicationException: TEIID20013 java.net.SocketException: Socket closed
> at org.teiid.net.socket.SocketServerInstanceImpl.send(SocketServerInstanceImpl.java:217) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at sun.reflect.GeneratedMethodAccessor24.invoke(Unknown Source) ~[?:?]
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[?:1.8.0_121]
> at java.lang.reflect.Method.invoke(Unknown Source) ~[?:1.8.0_121]
> at org.teiid.net.socket.SocketServerConnectionFactory$ShutdownHandler.invoke(SocketServerConnectionFactory.java:98) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at com.sun.proxy.$Proxy21.send(Unknown Source) ~[?:?]
> at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler.invoke(SocketServerInstanceImpl.java:433) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.teiid.net.socket.SocketServerConnection$1.invoke(SocketServerConnection.java:293) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at com.sun.proxy.$Proxy24.closeRequest(Unknown Source) ~[?:?]
> at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:164) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> ... 9 more
> Caused by: java.util.concurrent.ExecutionException: java.net.SocketException: Socket closed
> at org.teiid.client.util.ResultsFuture.convertResult(ResultsFuture.java:104) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.teiid.client.util.ResultsFuture.get(ResultsFuture.java:99) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.teiid.net.socket.SocketServerInstanceImpl.send(SocketServerInstanceImpl.java:214) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at sun.reflect.GeneratedMethodAccessor24.invoke(Unknown Source) ~[?:?]
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[?:1.8.0_121]
> at java.lang.reflect.Method.invoke(Unknown Source) ~[?:1.8.0_121]
> at org.teiid.net.socket.SocketServerConnectionFactory$ShutdownHandler.invoke(SocketServerConnectionFactory.java:98) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at com.sun.proxy.$Proxy21.send(Unknown Source) ~[?:?]
> at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler.invoke(SocketServerInstanceImpl.java:433) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.teiid.net.socket.SocketServerConnection$1.invoke(SocketServerConnection.java:293) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at com.sun.proxy.$Proxy24.closeRequest(Unknown Source) ~[?:?]
> at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:164) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> ... 9 more
> Caused by: java.net.SocketException: Socket closed
> at java.net.SocketOutputStream.socketWrite(Unknown Source) ~[?:1.8.0_121]
> at java.net.SocketOutputStream.write(Unknown Source) ~[?:1.8.0_121]
> at java.io.DataOutputStream.write(Unknown Source) ~[?:1.8.0_121]
> at org.teiid.core.util.MultiArrayOutputStream.writeTo(MultiArrayOutputStream.java:94) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.teiid.netty.handler.codec.serialization.ObjectEncoderOutputStream.writeObjectOverride(ObjectEncoderOutputStream.java:70) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at java.io.ObjectOutputStream.writeObject(Unknown Source) ~[?:1.8.0_121]
> at org.teiid.net.socket.OioOjbectChannelFactory$OioObjectChannel.write(OioOjbectChannelFactory.java:136) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.teiid.net.socket.SocketServerInstanceImpl.send(SocketServerInstanceImpl.java:213) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at sun.reflect.GeneratedMethodAccessor24.invoke(Unknown Source) ~[?:?]
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[?:1.8.0_121]
> at java.lang.reflect.Method.invoke(Unknown Source) ~[?:1.8.0_121]
> at org.teiid.net.socket.SocketServerConnectionFactory$ShutdownHandler.invoke(SocketServerConnectionFactory.java:98) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at com.sun.proxy.$Proxy21.send(Unknown Source) ~[?:?]
> at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler.invoke(SocketServerInstanceImpl.java:433) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.teiid.net.socket.SocketServerConnection$1.invoke(SocketServerConnection.java:293) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at com.sun.proxy.$Proxy24.closeRequest(Unknown Source) ~[?:?]
> at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:164) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> ... 9 more
> {code}
> Server-side log excerpt, after raising logger levels to Debug:
> {code}
> 2017-12-15 12:00:45.625 [NIO36 ] DEBUG - processing message:MessageHolder: key=550774 contents=Invoke interface org.teiid.client.DQP.executeRequest
> 2017-12-15 12:00:47.730 [ocessorQueue14017479] DEBUG - send message: MessageHolder: key=550774 contents=ResultsMessage rowCount=256 finalRow=-1
> 2017-12-15 12:00:47.737 [NIO36 ] DEBUG - processing message:MessageHolder: key=550776 contents=Invoke interface org.teiid.client.DQP.processCursorRequest
> 2017-12-15 12:00:47.738 [ocessorQueue14017553] DEBUG - send message: MessageHolder: key=550776 contents=ResultsMessage rowCount=2048 finalRow=-1
> 2017-12-15 12:00:47.755 [NIO36 ] DEBUG - processing message:MessageHolder: key=550777 contents=Invoke interface org.teiid.client.DQP.processCursorRequest
> 2017-12-15 12:00:47.756 [ocessorQueue14017554] DEBUG - send message: MessageHolder: key=550777 contents=ResultsMessage rowCount=2048 finalRow=-1
> 2017-12-15 12:00:48.389 [NIO36 ] DEBUG - processing message:MessageHolder: key=550778 contents=Invoke interface org.teiid.client.DQP.processCursorRequest
> 2017-12-15 12:00:48.389 [ocessorQueue14017556] DEBUG - send message: MessageHolder: key=550778 contents=ResultsMessage rowCount=2048 finalRow=-1
> 2017-12-15 12:00:48.825 [NIO36 ] DEBUG - processing message:MessageHolder: key=550779 contents=Invoke interface org.teiid.client.DQP.processCursorRequest
> 2017-12-15 12:00:48.826 [ocessorQueue14017557] DEBUG - send message: MessageHolder: key=550779 contents=ResultsMessage rowCount=2048 finalRow=-1
> 2017-12-15 12:00:48.932 [NIO36 ] DEBUG - processing message:MessageHolder: key=550780 contents=Invoke interface org.teiid.client.DQP.processCursorRequest
> 2017-12-15 12:00:48.933 [ocessorQueue14017558] DEBUG - send message: MessageHolder: key=550780 contents=ResultsMessage rowCount=2048 finalRow=-1
> 2017-12-15 12:02:18.386 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:05:55.327 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:09:29.545 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:13:08.903 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:16:41.864 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:20:16.875 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:23:57.860 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:27:30.273 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:31:07.795 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:34:46.439 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:38:23.325 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:41:59.227 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:45:35.526 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:49:14.088 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:52:46.177 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:56:24.407 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 13:00:03.109 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 13:00:52.143 [NIO36 ] DEBUG - TEIID40114 Unhandled exception, closing client instance: Connection reset by peer
> java.io.IOException: Connection reset by peer
> at sun.nio.ch.FileDispatcherImpl.read0(Native Method)
> at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39)
> at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:223)
> at sun.nio.ch.IOUtil.read(IOUtil.java:192)
> at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:380)
> at io.netty.buffer.UnpooledUnsafeDirectByteBuf.setBytes(UnpooledUnsafeDirectByteBuf.java:447)
> at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:880)
> at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:242)
> at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:119)
> at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:511)
> at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:468)
> at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:382)
> at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:354)
> at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:112)
> at java.lang.Thread.run(Thread.java:745)
> 2017-12-15 13:00:52.143 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 13:03:34.811 [NIO36 ] DEBUG - Channel closed
> {code}
> Legend:
> * 'Channel closed' is logged from org.teiid.transport.SSLAwareChannelHandler class, and its channelInactive method;
> * 'MessageHolder' logs are from org.teiid.net.socket.Message;
> * the log lines that contain rowCount, finalRow, etc. are coming from org.teiid.transport.SocketClientInstance.
--
This message was sent by Atlassian JIRA
(v7.5.0#75005)
6 years, 4 months
- 1
- 0