SEVERE: There was an unhandled exception from the protocol handler

[r...@swirrl.com]

Hi. We're running Stardog 3.1, and saw the error below in stardog.log multiple times between 9am and about 12:30 this morning. Shortly before 9am, there were some java.lang.OutOfMemoryError errors too. 

This caused clients to the database (over the http SPARQL API) to experience intermittent errors connecting and executing queries, but the database process stayed up. Restarting Stardog made the problem go away.

The database had been running fine for several weeks before this time.

Regards,

Ric.

Jul 08, 2015 12:23:17 PM com.complexible.common.protocols.server.rpc.ProtocolHandler exceptionCaught
SEVERE: There was an unhandled exception from the protocol handler
io.netty.handler.codec.DecoderException: java.lang.IllegalArgumentException: Duplicate handler name: HTTP Codec
	at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:299)
	at io.netty.handler.codec.ByteToMessageDecoder.channelInactive(ByteToMessageDecoder.java:224)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:208)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:194)
	at io.netty.channel.DefaultChannelPipeline.fireChannelInactive(DefaultChannelPipeline.java:828)
	at io.netty.channel.AbstractChannel$AbstractUnsafe$5.run(AbstractChannel.java:576)
	at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:380)
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:357)
	at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:116)
	at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.IllegalArgumentException: Duplicate handler name: HTTP Codec
	at io.netty.channel.DefaultChannelPipeline.checkDuplicateName(DefaultChannelPipeline.java:959)
	at io.netty.channel.DefaultChannelPipeline.addLast(DefaultChannelPipeline.java:126)
	at io.netty.channel.DefaultChannelPipeline.addLast(DefaultChannelPipeline.java:120)
	at com.complexible.stardog.protocols.http.server.HTTPServerProtocol.apply(HTTPServerProtocol.java:175)
	at com.complexible.common.protocols.server.rpc.ProtocolHandler.decode(ProtocolHandler.java:144)
	at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:268)
	... 9 more

Jul 08, 2015 12:23:17 PM io.netty.util.internal.logging.Slf4JLogger warn
WARNING: Failed to submit an exceptionCaught() event.
java.util.concurrent.RejectedExecutionException: event executor terminated
	at io.netty.util.concurrent.SingleThreadEventExecutor.reject(SingleThreadEventExecutor.java:745)
	at io.netty.util.concurrent.SingleThreadEventExecutor.addTask(SingleThreadEventExecutor.java:322)
	at io.netty.util.concurrent.SingleThreadEventExecutor.execute(SingleThreadEventExecutor.java:728)
	at io.netty.channel.AbstractChannelHandlerContext.fireExceptionCaught(AbstractChannelHandlerContext.java:227)
	at io.netty.channel.ChannelHandlerAdapter.exceptionCaught(ChannelHandlerAdapter.java:79)
	at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:246)
	at io.netty.channel.AbstractChannelHandlerContext.fireExceptionCaught(AbstractChannelHandlerContext.java:224)
	at io.netty.channel.ChannelInboundHandlerAdapter.exceptionCaught(ChannelInboundHandlerAdapter.java:131)
	at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:246)
	at io.netty.channel.AbstractChannelHandlerContext.notifyHandlerException(AbstractChannelHandlerContext.java:737)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:160)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelUnregistered(AbstractChannelHandlerContext.java:144)
	at io.netty.channel.ChannelInboundHandlerAdapter.channelUnregistered(ChannelInboundHandlerAdapter.java:53)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:158)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelUnregistered(AbstractChannelHandlerContext.java:144)
	at io.netty.channel.ChannelInboundHandlerAdapter.channelUnregistered(ChannelInboundHandlerAdapter.java:53)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:158)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelUnregistered(AbstractChannelHandlerContext.java:144)
	at io.netty.channel.ChannelInboundHandlerAdapter.channelUnregistered(ChannelInboundHandlerAdapter.java:53)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:158)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelUnregistered(AbstractChannelHandlerContext.java:144)
	at io.netty.channel.ChannelInboundHandlerAdapter.channelUnregistered(ChannelInboundHandlerAdapter.java:53)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:158)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelUnregistered(AbstractChannelHandlerContext.java:144)
	at io.netty.channel.ChannelInboundHandlerAdapter.channelUnregistered(ChannelInboundHandlerAdapter.java:53)
	at io.netty.channel.CombinedChannelDuplexHandler.channelUnregistered(CombinedChannelDuplexHandler.java:122)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:158)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelUnregistered(AbstractChannelHandlerContext.java:144)
	at io.netty.channel.ChannelInboundHandlerAdapter.channelUnregistered(ChannelInboundHandlerAdapter.java:53)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:158)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelUnregistered(AbstractChannelHandlerContext.java:144)
	at io.netty.channel.DefaultChannelPipeline.fireChannelUnregistered(DefaultChannelPipeline.java:739)
	at io.netty.channel.AbstractChannel$AbstractUnsafe$6.run(AbstractChannel.java:615)
	at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:380)
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:357)
	at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:116)
	at java.lang.Thread.run(Thread.java:745)

Jul 08, 2015 12:23:17 PM io.netty.util.internal.logging.Slf4JLogger warn
WARNING: The exceptionCaught() event that was failed to submit was:
java.util.concurrent.RejectedExecutionException: event executor terminated
	at io.netty.util.concurrent.SingleThreadEventExecutor.reject(SingleThreadEventExecutor.java:745)
	at io.netty.util.concurrent.SingleThreadEventExecutor.addTask(SingleThreadEventExecutor.java:322)
	at io.netty.util.concurrent.SingleThreadEventExecutor.execute(SingleThreadEventExecutor.java:728)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelUnregistered(AbstractChannelHandlerContext.java:146)
	at io.netty.channel.ChannelInboundHandlerAdapter.channelUnregistered(ChannelInboundHandlerAdapter.java:53)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:158)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelUnregistered(AbstractChannelHandlerContext.java:144)
	at io.netty.channel.ChannelInboundHandlerAdapter.channelUnregistered(ChannelInboundHandlerAdapter.java:53)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:158)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelUnregistered(AbstractChannelHandlerContext.java:144)
	at io.netty.channel.ChannelInboundHandlerAdapter.channelUnregistered(ChannelInboundHandlerAdapter.java:53)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:158)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelUnregistered(AbstractChannelHandlerContext.java:144)
	at io.netty.channel.ChannelInboundHandlerAdapter.channelUnregistered(ChannelInboundHandlerAdapter.java:53)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:158)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelUnregistered(AbstractChannelHandlerContext.java:144)
	at io.netty.channel.ChannelInboundHandlerAdapter.channelUnregistered(ChannelInboundHandlerAdapter.java:53)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:158)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelUnregistered(AbstractChannelHandlerContext.java:144)
	at io.netty.channel.ChannelInboundHandlerAdapter.channelUnregistered(ChannelInboundHandlerAdapter.java:53)
	at io.netty.channel.CombinedChannelDuplexHandler.channelUnregistered(CombinedChannelDuplexHandler.java:122)

[Michael Grove]

On Wed, Jul 8, 2015 at 9:33 AM, <r...@swirrl.com> wrote:

Hi. We're running Stardog 3.1, and saw the error below in stardog.log multiple times between 9am and about 12:30 this morning. Shortly before 9am, there were some java.lang.OutOfMemoryError errors too. 

Without having the rest of the log, my feeling is that these are probably cause by the OOM, which I'm more curious about.

Was it a particular query that caused this, or, just high load?  If a particular query, could you share?

 

This caused clients to the database (over the http SPARQL API) to experience intermittent errors connecting and executing queries, but the database process stayed up. Restarting Stardog made the problem go away.

Glad things kept chugging along, mostly working.  The restart fixing the problem I think confirms my suspicion that the protocol errors were somehow caused by the OOM.

Cheers,

Mike

 

--
-- --
You received this message because you are subscribed to the C&P "Stardog" group.
To post to this group, send email to sta...@clarkparsia.com
To unsubscribe from this group, send email to
stardog+u...@clarkparsia.com
For more options, visit this group at
http://groups.google.com/a/clarkparsia.com/group/stardog?hl=en

[Rick Moynihan]

I had a similar feeling about the OOM being the root cause too.

I was surprised however that stardog kept running after an Error was raised though.  I thought the recommended thing to do was simply to log errors and die; first by trying to shutdown gracefully and then by simply dying.

The fact that stardog has kept running in an inconsistent state for a long time afterwards returning potentially incorrect results because it's in an inconsistent state internally seems like the worst thing to do.  At least if it dies we can just restart it with monit and continue in a consistent state.

R.

To unsubscribe from this group and stop receiving emails from it, send an email to stardog+u...@clarkparsia.com.

[Michael Grove]

On Thu, Jul 9, 2015 at 7:30 AM, Rick Moynihan <ric...@swirrl.com> wrote:

I had a similar feeling about the OOM being the root cause too.

I was surprised however that stardog kept running after an Error was raised though.  I thought the recommended thing to do was simply to log errors and die; first by trying to shutdown gracefully and then by simply dying.

The recommended way to do that is with the JVM flag `-XX:OnOutOfMemoryError`.

Cheers,

Mike

[Michael Grove]

On Thu, Jul 9, 2015 at 8:37 AM, Michael Grove <mi...@complexible.com> wrote:

On Thu, Jul 9, 2015 at 7:30 AM, Rick Moynihan <ric...@swirrl.com> wrote:

I had a similar feeling about the OOM being the root cause too.

Can you share the details of how the OOM occurred so that we can see if there's anything we can do to address the situation?

If the query and/or data is private, we can arrange something off list.

Cheers,

Mike

[Ric Roberts]

It wasn't under particularly high load. The site is in semi-public beta. A couple of people in our company were querying the database at around that time - I'll ask regarding what queries they were running.

As Rick said, I think we'd prefer if it died and we could restart it. The inconsistent behaviour caused us to lose almost a day of developer time diagnosing a problem that we thought was in our code (but was actually due to this problem).

[Rick Moynihan]

Thanks for the tip on -XX:OnOutOfMemoryError, I hadn't seen that before.

What do you recommend users do in these circumstances though?  Should we -XX:OnOutOfMemoryError="kill %p".

Would it make sense for this to be included in the default Unix start script?

R.

[Michael Grove]

On Thu, Jul 9, 2015 at 9:37 AM, Rick Moynihan <ric...@swirrl.com> wrote:

Thanks for the tip on -XX:OnOutOfMemoryError, I hadn't seen that before.

What do you recommend users do in these circumstances though?  Should we -XX:OnOutOfMemoryError="kill %p".

No.  I think better would be something like "stardog-admin server stop ; stardog-admin server start" for the restart.  Kill should send the correct signal to the JVM for a clean shutdown, but it's preferable to use `server stop`.

 

Would it make sense for this to be included in the default Unix start script?

Maybe?  I have not included it before because I didn't want to presume that is the best course of action for everyone.  And it's obscure enough that I think if it did happen automatically, people would not necessarily think to look in the script for changing the behavior.

Cheers,

Mike

[Bill Roberts]

Hi Mike

I’m not certain it was the cause of the OOM, but I was trying to count the number of triples in each RDF Data Cube dataset in a billion triple database at around that time.  I later found a quick and efficient query to do it, but attempt 1 was something like the following - and timed out in our client software.  Not sure what the current timeout settings of Stardog itself are

PREFIX qb: <http://purl.org/linked-data/cube#>

SELECT (count(?s) as ?c) ?ds

WHERE {

  ?ds a qb:DataSet .

  ?s qb:dataSet ?ds .

  ?s ?p ?o

} GROUP BY ?ds

Incidentally it seems that (count(*) as ?c) is generally a lot quicker in Stardog than (count(?s) as ?c) in circumstances like this.

[Michael Grove]

On Thu, Jul 9, 2015 at 10:22 AM, Bill Roberts <bi...@swirrl.com> wrote:

Hi Mike

I’m not certain it was the cause of the OOM, but I was trying to count the number of triples in each RDF Data Cube dataset in a billion triple database at around that time.  I later found a quick and efficient query to do it, but attempt 1 was something like the following - and timed out in our client software.  Not sure what the current timeout settings of Stardog itself are

PREFIX qb: <http://purl.org/linked-data/cube#>

SELECT (count(?s) as ?c) ?ds

WHERE {

  ?ds a qb:DataSet .

  ?s qb:dataSet ?ds .

  ?s ?p ?o

} GROUP BY ?ds

Incidentally it seems that (count(*) as ?c) is generally a lot quicker in Stardog than (count(?s) as ?c) in circumstances like this.

What are the query plans you get from explain for each variant of the query?

Cheers,

Mike