Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Getting deserialization errors from asynchbase when enabling appends on opentsdb (2.2) #118

Closed
alienth opened this issue Sep 9, 2015 · 6 comments
Closed

Getting deserialization errors from asynchbase when enabling appends on opentsdb (2.2) #118

alienth opened this issue Sep 9, 2015 · 6 comments

Comments

@alienth
Copy link

alienth commented Sep 9, 2015

I installed opentsdb 2.2 on a preexisting 2.1 setup. 2.2 initially worked AOK, but when enabling appends I started getting the following spewed to my opentsdb.log. Discussed in the #opentsdb channel and manolama indicated this is an AsyncHBase error.

2015-09-09 19:18:21,266 ERROR [New I/O worker #49] [RegionClient.decode] - Uncaught error during de-serialization of MultiAction(batch=[AppendRequest(table="tsdb", key=[0, 1, 4, 85, -16, -127, -80, 0, 0, 3, 0, 13, -62], family="t", qualifiers=[[5, 0, 0]], values=["D\xA0\x06"], timestamp=9223372036854775807, lockid=-1, durable=true, return_result=false, bufferable=true, attempt=1, region=RegionInfo(table="tsdb", region_name="tsdb,\x00\x01\x04U\xC5*`\x00\x00\x03\x00\x07\xDC,1440194511347.cf3baaae682713e3924fa7e39685d746.", stop_key=[0, 1, 106, 85, -47, 120, 96, 0, 0, 3, 0, 7, -125])), AppendRequest(table="tsdb", key=[0, 1, 5, 85, -16, -127, -80, 0, 0, 3, 0, 13, -62], family="t", qualifiers=[[5, 0, 0]], values=[[68, -93, 0, 2, 83, 1]], timestamp=9223372036854775807, lockid=-1, durable=true, return_result=false, bufferable=true, attempt=1, region=RegionInfo(table="tsdb", region_name="tsdb,\x00\x01\x04U\xC5*`\x00\x00\x03\x00\x07\xDC,1440194511347.cf3baaae682713e3924fa7e39685d746.", stop_key=[0, 1, 106, 85, -47, 120, 96, 0, 0, 3, 0, 7, -125])), AppendRequest(table="tsdb", key=[0, 1, 6, 85, -16, -127, -80, 0, 0, 3, 0, 13, -62], family="t", qualifiers=[[5, 0, 0]], values=["D\xA1+p"], timestamp=9223372036854775807, lockid=-1, durable=true, return_result=false, bufferable=true, attempt=1, region=RegionInfo(table="tsdb", region_name="tsdb,\x00\x01\x04U\xC5*`\x00\x00\x03\x00\x07\xDC,1440194511347.cf3baaae682713e3924fa7e39685d746.", stop_key=[0, 1, 106, 85, -47, 120, 96, 0, 0, 3, 0, 7, -125])), ... 428 RPCs not shown ..., AppendRequest(table="tsdb", key=[0, 11, 25, 85, -16, -127, -80, 0, 0, 1, 0, 0, 1, 0, 0, 3, 0, 9, 41], family="t", qualifiers=[[5, 0, 0]], values=[[68, -77, 0, 1, 101, -99]], timestamp=9223372036854775807, lockid=-1, durable=true, return_result=false, bufferable=true, attempt=2, region=RegionInfo(table="tsdb", region_name="tsdb,\x00\n\xE3U\xDB\xA1\xF0\x00\x00\x03\x00\x12\xDC\x00\x00\x11\x00%&\x00\x00r\x00%%,1441241759344.f9ef3261287b9bdd5e804428248ff54d.", stop_key=""))]), rpcid=6910

Running on hbase 1.0.0-cdh5.4.4.
@alienth
Copy link
Author

alienth commented Sep 9, 2015

Pcap between opentsdb and hbase during the incident can be found here: https://docs.google.com/uc?id=0BzLBsbBPE3yoVFk3M29JSVpWZzQ&export=download

@alienth
Copy link
Author

alienth commented Sep 9, 2015

Log from opentsdb with asynchbase debug logging enabled: https://gist.githubusercontent.com/alienth/bbdf8f8191584bbbcb00/raw/5af388c9d26c57a170b877ed4f1edf352c5c94fc/gistfile1.txt

@alienth alienth closed this as completed Sep 9, 2015
@alienth alienth reopened this Sep 9, 2015
@alienth
Copy link
Author

alienth commented Sep 9, 2015

Existing debug logs were for an older version of asynchbase. Newest build also exhibits the same issue. I'll provide new debug logs so that the line numbers make sense.

@alienth
Copy link
Author

alienth commented Sep 9, 2015

Exception log for latest version:


2015-09-09 23:44:35,625 ERROR [AsyncHBase I/O Worker #1] [RegionClient.decode] - Uncaught error during de-serialization of MultiAction(batch=[AppendRequest(table="tsdb", key=[0, 0, -38, 85, -16, -71, -16, 0, 0, 3, 0, 24, -95], family="t", qualifiers=[[5, 0, 0]], values=[[-107, 43, 63, -64, 0, 0]], timestamp=9223372036854775807, lockid=-1, durable=true, return_result=false, bufferable=true, attempt=1, region=RegionInfo(table="tsdb", region_name="tsdb,\x00\x00\xD5U\xCC\xB0\xF0\x00\x00\x03\x00\x02\x16\x00\x00\x08\x00\x00\x0F\x00\x00\x0E\x00\x00I,1439514155676.9df312a9f0d265f4c30bcc15701920aa.", stop_key=[0, 0, -29, 85, -58, -90, 16, 0, 0, 3, 0, 3, 58, 0, 0, 8, 0, 0, 113, 0, 0, 14, 0, 0, 102])), AppendRequest(table="tsdb", key=[0, 0, -38, 85, -16, -71, -16, 0, 0, 3, 0, 24, -95], family="t", qualifiers=[[5, 0, 0]], values=[[-107, 27, 63, -64, 0, 0]], timestamp=9223372036854775807, lockid=-1, durable=true, return_result=false, bufferable=true, attempt=1, region=RegionInfo(table="tsdb", region_name="tsdb,\x00\x00\xD5U\xCC\xB0\xF0\x00\x00\x03\x00\x02\x16\x00\x00\x08\x00\x00\x0F\x00\x00\x0E\x00\x00I,1439514155676.9df312a9f0d265f4c30bcc15701920aa.", stop_key=[0, 0, -29, 85, -58, -90, 16, 0, 0, 3, 0, 3, 58, 0, 0, 8, 0, 0, 113, 0, 0, 14, 0, 0, 102])), ... 1021 RPCs not shown ..., AppendRequest(table="tsdb", key=[0, 0, -38, 85, -16, -71, -16, 0, 0, 3, 0, 24, -95], family="t", qualifiers=[[5, 0, 0]], values=["U[?\xC0\x00\x00"], timestamp=9223372036854775807, lockid=-1, durable=true, return_result=false, bufferable=true, attempt=1, region=RegionInfo(table="tsdb", region_name="tsdb,\x00\x00\xD5U\xCC\xB0\xF0\x00\x00\x03\x00\x02\x16\x00\x00\x08\x00\x00\x0F\x00\x00\x0E\x00\x00I,1439514155676.9df312a9f0d265f4c30bcc15701920aa.", stop_key=[0, 0, -29, 85, -58, -90, 16, 0, 0, 3, 0, 3, 58, 0, 0, 8, 0, 0, 113, 0, 0, 14, 0, 0, 102]))]), rpcid=449
2015-09-09 23:44:35,627 ERROR [AsyncHBase I/O Worker #1] [RegionClient.exceptionCaught] - Unexpected exception from downstream on [id: 0xd7cdaadd, /10.8.0.231:55731 => /10.8.0.231:60020]
org.hbase.async.NonRecoverableException: Uncaught error during de-serialization of MultiAction(batch=[AppendRequest(table="tsdb", key=[0, 0, -38, 85, -16, -71, -16, 0, 0, 3, 0, 24, -95], family="t", qualifiers=[[5, 0, 0]], values=[[-107, 43, 63, -64, 0, 0]], timestamp=9223372036854775807, lockid=-1, durable=true, return_result=false, bufferable=true, attempt=1, region=RegionInfo(table="tsdb", region_name="tsdb,\x00\x00\xD5U\xCC\xB0\xF0\x00\x00\x03\x00\x02\x16\x00\x00\x08\x00\x00\x0F\x00\x00\x0E\x00\x00I,1439514155676.9df312a9f0d265f4c30bcc15701920aa.", stop_key=[0, 0, -29, 85, -58, -90, 16, 0, 0, 3, 0, 3, 58, 0, 0, 8, 0, 0, 113, 0, 0, 14, 0, 0, 102])), AppendRequest(table="tsdb", key=[0, 0, -38, 85, -16, -71, -16, 0, 0, 3, 0, 24, -95], family="t", qualifiers=[[5, 0, 0]], values=[[-107, 27, 63, -64, 0, 0]], timestamp=9223372036854775807, lockid=-1, durable=true, return_result=false, bufferable=true, attempt=1, region=RegionInfo(table="tsdb", region_name="tsdb,\x00\x00\xD5U\xCC\xB0\xF0\x00\x00\x03\x00\x02\x16\x00\x00\x08\x00\x00\x0F\x00\x00\x0E\x00\x00I,1439514155676.9df312a9f0d265f4c30bcc15701920aa.", stop_key=[0, 0, -29, 85, -58, -90, 16, 0, 0, 3, 0, 3, 58, 0, 0, 8, 0, 0, 113, 0, 0, 14, 0, 0, 102])), ... 1021 RPCs not shown ..., AppendRequest(table="tsdb", key=[0, 0, -38, 85, -16, -71, -16, 0, 0, 3, 0, 24, -95], family="t", qualifiers=[[5, 0, 0]], values=["U[?\xC0\x00\x00"], timestamp=9223372036854775807, lockid=-1, durable=true, return_result=false, bufferable=true, attempt=1, region=RegionInfo(table="tsdb", region_name="tsdb,\x00\x00\xD5U\xCC\xB0\xF0\x00\x00\x03\x00\x02\x16\x00\x00\x08\x00\x00\x0F\x00\x00\x0E\x00\x00I,1439514155676.9df312a9f0d265f4c30bcc15701920aa.", stop_key=[0, 0, -29, 85, -58, -90, 16, 0, 0, 3, 0, 3, 58, 0, 0, 8, 0, 0, 113, 0, 0, 14, 0, 0, 102]))]), rpcid=449
    at org.hbase.async.RegionClient.decode(RegionClient.java:1485) ~[asynchbase-1.7.0-20150904.040751-2.jar:na]
    at org.hbase.async.RegionClient.decode(RegionClient.java:88) ~[asynchbase-1.7.0-20150904.040751-2.jar:na]
    at org.jboss.netty.handler.codec.replay.ReplayingDecoder.callDecode(ReplayingDecoder.java:500) ~[netty-3.9.4.Final.jar:na]
    at org.jboss.netty.handler.codec.replay.ReplayingDecoder.messageReceived(ReplayingDecoder.java:435) ~[netty-3.9.4.Final.jar:na]
    at org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:70) [netty-3.9.4.Final.jar:na]
    at org.hbase.async.RegionClient.handleUpstream(RegionClient.java:1206) ~[asynchbase-1.7.0-20150904.040751-2.jar:na]
    at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564) [netty-3.9.4.Final.jar:na]
    at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791) [netty-3.9.4.Final.jar:na]
    at org.jboss.netty.channel.SimpleChannelHandler.messageReceived(SimpleChannelHandler.java:142) [netty-3.9.4.Final.jar:na]
    at org.jboss.netty.channel.SimpleChannelHandler.handleUpstream(SimpleChannelHandler.java:88) [netty-3.9.4.Final.jar:na]
    at org.jboss.netty.handler.timeout.IdleStateAwareChannelHandler.handleUpstream(IdleStateAwareChannelHandler.java:36) [netty-3.9.4.Final.jar:na]
    at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564) [netty-3.9.4.Final.jar:na]
    at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791) [netty-3.9.4.Final.jar:na]
    at org.jboss.netty.handler.timeout.IdleStateHandler.messageReceived(IdleStateHandler.java:294) [netty-3.9.4.Final.jar:na]
    at org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:70) [netty-3.9.4.Final.jar:na]
    at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564) [netty-3.9.4.Final.jar:na]
    at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:559) [netty-3.9.4.Final.jar:na]
    at org.hbase.async.HBaseClient$RegionClientPipeline.sendUpstream(HBaseClient.java:2961) [asynchbase-1.7.0-20150904.040751-2.jar:na]
    at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:268) [netty-3.9.4.Final.jar:na]
    at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:255) [netty-3.9.4.Final.jar:na]
    at org.jboss.netty.channel.socket.nio.NioWorker.read(NioWorker.java:88) [netty-3.9.4.Final.jar:na]
    at org.jboss.netty.channel.socket.nio.AbstractNioWorker.process(AbstractNioWorker.java:108) [netty-3.9.4.Final.jar:na]
    at org.jboss.netty.channel.socket.nio.AbstractNioSelector.run(AbstractNioSelector.java:318) [netty-3.9.4.Final.jar:na]
    at org.jboss.netty.channel.socket.nio.AbstractNioWorker.run(AbstractNioWorker.java:89) [netty-3.9.4.Final.jar:na]
    at org.jboss.netty.channel.socket.nio.NioWorker.run(NioWorker.java:178) [netty-3.9.4.Final.jar:na]
    at org.jboss.netty.util.ThreadRenamingRunnable.run(ThreadRenamingRunnable.java:108) [netty-3.9.4.Final.jar:na]
    at org.jboss.netty.util.internal.DeadLockProofWorker$1.run(DeadLockProofWorker.java:42) [netty-3.9.4.Final.jar:na]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [na:1.7.0_79]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [na:1.7.0_79]
    at java.lang.Thread.run(Thread.java:745) [na:1.7.0_79]
Caused by: java.lang.IndexOutOfBoundsException: Index: 1024, Size: 1024
    at java.util.ArrayList.rangeCheck(ArrayList.java:635) ~[na:1.7.0_79]
    at java.util.ArrayList.get(ArrayList.java:411) ~[na:1.7.0_79]
    at org.hbase.async.MultiAction.deserialize(MultiAction.java:597) ~[asynchbase-1.7.0-20150904.040751-2.jar:na]
    at org.hbase.async.RegionClient.decode(RegionClient.java:1475) ~[asynchbase-1.7.0-20150904.040751-2.jar:na]
    ... 29 common frames omitted

@manolama
Copy link
Member

manolama commented Sep 9, 2015

Thanks! And could you capture the packets around this kind of error to please?

manolama added a commit to manolama/asynchbase that referenced this issue Sep 10, 2015
@manolama
Fix OpenTSDB#118 by properly parsing out append responses in a multi …
8db357f 
…action

that appear after the last returned response. E.g. if the multi
action had an append -> put -> append, we would throw an IOOBE
and fail to properly parse the append. Thanks @alienth
manolama added a commit that referenced this issue Sep 10, 2015
@manolama
Fix #118 by properly parsing out append responses in a multi action
69641a2 
that appear after the last returned response. E.g. if the multi
action had an append -> put -> append, we would throw an IOOBE
and fail to properly parse the append. Thanks @alienth

Signed-off-by: Chris Larsen <clarsen@yahoo-inc.com>
@manolama
Copy link
Member

Fixed with manolama@8db357f

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@alienth @manolama