{"action":"created","issue":{"url":"https://api.github.com/repos/pravega/pravega/issues/2664","repository_url":"https://api.github.com/repos/pravega/pravega","labels_url":"https://api.github.com/repos/pravega/pravega/issues/2664/labels{/name}","comments_url":"https://api.github.com/repos/pravega/pravega/issues/2664/comments","events_url":"https://api.github.com/repos/pravega/pravega/issues/2664/events","html_url":"https://github.com/pravega/pravega/issues/2664","id":329549190,"node_id":"MDU6SXNzdWUzMjk1NDkxOTA=","number":2664,"title":"Reader failing with TruncatedDataException","user":{"login":"jkhalack","id":25368596,"node_id":"MDQ6VXNlcjI1MzY4NTk2","avatar_url":"https://avatars2.githubusercontent.com/u/25368596?v=4","gravatar_id":"","url":"https://api.github.com/users/jkhalack","html_url":"https://github.com/jkhalack","followers_url":"https://api.github.com/users/jkhalack/followers","following_url":"https://api.github.com/users/jkhalack/following{/other_user}","gists_url":"https://api.github.com/users/jkhalack/gists{/gist_id}","starred_url":"https://api.github.com/users/jkhalack/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/jkhalack/subscriptions","organizations_url":"https://api.github.com/users/jkhalack/orgs","repos_url":"https://api.github.com/users/jkhalack/repos","events_url":"https://api.github.com/users/jkhalack/events{/privacy}","received_events_url":"https://api.github.com/users/jkhalack/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":0,"created_at":"2018-06-05T17:14:43Z","updated_at":"2018-06-05T17:16:39Z","closed_at":null,"author_association":"COLLABORATOR","body":"**Problem description**\r\nOn streams with dynamic scaling where the number of routing keys (20) is less than the average number of active segments (so some of the segments are empty) the readers are sometimes failing with `TruncatedDataException`.\r\n\r\nFor the `smallScaleSlow` stream shown in the segment heat chart below, there is a writer group of three writers and a reader group of one TAIL reader. \r\nAt 3 hours 18 minutes after the start of our longevity test (that would be 12:17 chart time and 15:17 log time) the only reader finishes with `io.pravega.client.stream.TruncatedDataException`:\r\n```\r\n2018-06-05 15:17:35,137 11683422 [pool-8-thread-1] INFO  c.e.n.h.t.w.readers.PravegaReader - Removed Reader HulkSmallScaleSlow278f1654ead84e5999417823161e9505 from ReaderGroup HulkSmallScaleSlow at position hulk/smallScaleSlow/129=957719, hulk/smallScaleSlow/136=680764, hulk/smallScaleSlow/158=450590, hulk/smallScaleSlow/125=644602, hulk/smallScaleSlow/148=0, hulk/smallScaleSlow/115=1457960, hulk/smallScaleSlow/159=443702, hulk/smallScaleSlow/127=0, hulk/smallScaleSlow/128=668423, hulk/smallScaleSlow/132=707455, hulk/smallScaleSlow/113=0, hulk/smallScaleSlow/79=0, hulk/smallScaleSlow/173=99876, hulk/smallScaleSlow/174=112504, hulk/smallScaleSlow/152=702576\r\n2018-06-05 15:17:35,143 11683428 [pool-8-thread-1] ERROR c.e.n.h.t.w.r.ReaderWorkerManager - Reader Finished with Error\r\nio.pravega.client.stream.TruncatedDataException: null\r\n\tat io.pravega.client.stream.impl.EventStreamReaderImpl.handleSegmentTruncated(EventStreamReaderImpl.java:234)\r\n\tat io.pravega.client.stream.impl.EventStreamReaderImpl.readNextEvent(EventStreamReaderImpl.java:110)\r\n\tat com.emc.nautilus.hulk.taskexecutor.workers.readers.PravegaReader.start(PravegaReader.java:96)\r\n\tat java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)\r\n\tat java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)\r\n\tat java.lang.Thread.run(Unknown Source)\r\n```\r\n\r\nBefore this error there are a few attempts to read from segment `hulk/smallScaleSlow/79`:\r\n```\r\n2018-06-05 14:13:32,086 7840371 [pool-8-thread-1] INFO  i.p.c.s.impl.EventStreamReaderImpl - EventStreamReaderImpl( id=HulkSmallScaleSlow278f1654ead84e5999417823161e9505) acquiring segments {hulk/smallScaleSlow/79=0, hulk/smallScaleSlow/80=0}\r\n\r\n...\r\n\r\n2018-06-05 15:17:33,899 11682184 [epollEventLoopGroup-5-11] INFO  i.p.c.s.i.AsyncSegmentInputStreamImpl - Closing connection to segment hulk/smallScaleSlow/79 with exception: {}\r\nio.pravega.shared.protocol.netty.ConnectionFailedException: null\r\n\tat io.pravega.client.segment.impl.AsyncSegmentInputStreamImpl$ResponseProcessor.connectionDropped(AsyncSegmentInputStreamImpl.java:60)\r\n\tat io.pravega.client.netty.impl.ClientConnectionInboundHandler.channelUnregistered(ClientConnectionInboundHandler.java:86)\r\n\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:181)\r\n...\r\n2018-06-05 15:17:33,900 11682185 [epollEventLoopGroup-5-11] INFO  i.p.c.s.i.AsyncSegmentInputStreamImpl - Connection failed due to a io.pravega.shared.protocol.netty.ConnectionFailedException. Read requests will be retransmitted.\r\n2018-06-05 15:17:33,900 11682185 [epollEventLoopGroup-5-11] WARN  i.p.c.s.i.AsyncSegmentInputStreamImpl - Exception while reading from Segment : hulk/smallScaleSlow/79\r\nio.pravega.shared.protocol.netty.ConnectionFailedException: null\r\n\tat io.pravega.client.segment.impl.AsyncSegmentInputStreamImpl$ResponseProcessor.connectionDropped(AsyncSegmentInputStreamImpl.java:60)\r\n\tat io.pravega.client.netty.impl.ClientConnectionInboundHandler.channelUnregistered(ClientConnectionInboundHandler.java:86)\r\n...\r\n2018-06-05 15:17:33,949 11682234 [epollEventLoopGroup-5-11] INFO  i.p.c.s.i.AsyncSegmentInputStreamImpl - Received noSuchSegment No such segment: hulk/smallScaleSlow/79\r\n2018-06-05 15:17:33,950 11682235 [epollEventLoopGroup-5-11] WARN  i.p.c.s.i.AsyncSegmentInputStreamImpl - Exception while reading from Segment : hulk/smallScaleSlow/79\r\nio.pravega.client.segment.impl.SegmentTruncatedException: Segment no longer exists.\r\n\tat io.pravega.client.segment.impl.AsyncSegmentInputStreamImpl$ResponseProcessor.noSuchSegment(AsyncSegmentInputStreamImpl.java:73)\r\n\tat io.pravega.shared.protocol.netty.WireCommands$NoSuchSegment.process(WireCommands.java:241)\r\n...\r\n2018-06-05 15:17:34,789 11683074 [pool-8-thread-1] INFO  i.p.c.s.impl.EventStreamReaderImpl - EventStreamReaderImpl( id=HulkSmallScaleSlow278f1654ead84e5999417823161e9505) encountered truncation for segment hulk/smallScaleSlow/79 \r\n...\r\n2018-06-05 15:17:34,819 11683104 [epollEventLoopGroup-5-12] INFO  i.p.c.s.i.SegmentMetadataClientImpl - Closing connection as a result of receiving: No such segment: hulk/smallScaleSlow/79\r\n2018-06-05 15:17:34,819 11683104 [epollEventLoopGroup-5-12] INFO  i.p.client.netty.impl.RawClient - Closing connection with exception: null\r\n2018-06-05 15:17:34,827 11683112 [epollEventLoopGroup-5-12] INFO  i.p.client.netty.impl.RawClient - Closing connection with exception: null\r\n2018-06-05 15:17:34,827 11683112 [pool-8-thread-1] INFO  i.p.c.s.impl.EventStreamReaderImpl - EventStreamReaderImpl( id=HulkSmallScaleSlow278f1654ead84e5999417823161e9505) encountered end of segment hulk/smallScaleSlow/79 \r\n2018-06-05 15:17:34,827 11683112 [pool-8-thread-1] INFO  i.p.c.s.i.AsyncSegmentInputStreamImpl - Closing reader for hulk/smallScaleSlow/79\r\n2018-06-05 15:17:34,827 11683112 [pool-8-thread-1] INFO  i.p.c.s.i.AsyncSegmentInputStreamImpl - Closing connection to segment: hulk/smallScaleSlow/79\r\n2018-06-05 15:17:34,827 11683112 [pool-8-thread-1] INFO  i.p.c.s.i.AsyncSegmentInputStreamImpl - Connection failed due to a io.pravega.client.stream.impl.ConnectionClosedException. Read requests will be retransmitted.\r\n2018-06-05 15:17:34,827 11683112 [epollEventLoopGroup-5-11] INFO  i.p.c.s.i.AsyncSegmentInputStreamImpl - Closing connection to segment: hulk/smallScaleSlow/79\r\n2018-06-05 15:17:34,827 11683112 [epollEventLoopGroup-5-11] INFO  i.p.c.s.i.AsyncSegmentInputStreamImpl - Connection failed due to a io.pravega.shared.protocol.netty.ConnectionFailedException. Read requests will be retransmitted.\r\n2018-06-05 15:17:34,886 11683171 [pool-8-thread-1] INFO  i.p.c.s.i.SegmentMetadataClientImpl - Closing segment metadata connection for hulk/smallScaleSlow/79\r\n2018-06-05 15:17:34,886 11683171 [pool-8-thread-1] INFO  i.p.c.s.i.SegmentMetadataClientImpl - Closing connection with exception: null\r\n2018-06-05 15:17:34,887 11683172 [pool-8-thread-1] ERROR c.e.n.h.t.w.readers.PravegaReader - Reader finished with Error\r\nio.pravega.client.stream.TruncatedDataException: null\r\n\tat io.pravega.client.stream.impl.EventStreamReaderImpl.handleSegmentTruncated(EventStreamReaderImpl.java:234)\r\n\tat io.pravega.client.stream.impl.EventStreamReaderImpl.readNextEvent(EventStreamReaderImpl.java:110)\r\n\tat com.emc.nautilus.hulk.taskexecutor.workers.readers.PravegaReader.start(PravegaReader.java:96)\r\n\tat java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)\r\n\tat java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)\r\n\tat java.lang.Thread.run(Unknown Source)\r\n```\r\nFrom the heat chart we can see that segment `79` was merged with `87` into new (empty) segment `106` at 11:10 AM chart time (14:10 log time). So it was assigned to the reader (at 14:13) only after it had been sealed. \r\n\r\nIt must have been truncated at 14:47 (unfortunately I don't have controller logs with that entry), as the next truncation at 15:17 does not show segment `79` as being present (the descendant segment `106` is listed with offset 0):\r\n```\r\n2018-06-05 15:17:32,047 12351471 [controllerpool-26] INFO  i.p.c.s.e.r.TruncateStreamTask - Truncating stream hulk/smallScaleSlow at stream cut: {97=419020, 99=452599, 100=425047, 101=427630, 102=429352, 103=604422, 104=122836, 105=126280, 106=0, 107=121975, 108=129437, 109=244811, 110=106764, 111=117096, 112=335790, 113=0, 83=772030, 91=0, 94=0, 95=446859}\r\n```\r\n\r\n![giant-man smallScaleSlow segment heat chart](https://user-images.githubusercontent.com/25368596/40989434-215ea0f0-68c4-11e8-8397-4ab6c66df4e8.png)\r\n\r\n[stdout.controller.giant-man.June5.log](https://github.com/pravega/pravega/files/2073177/stdout.controller.giant-man.June5.log)\r\n[giant-man.smallScaleSlow.truncatedData.controller-server.June5.log](https://github.com/pravega/pravega/files/2073179/giant-man.smallScaleSlow.truncatedData.controller-server.June5.log)\r\n\r\nCommit https://github.com/pravega/pravega/commit/6de4965871fd6b1767e0114b1a4768a9896f01cf was used to run the test.\r\n\r\n**Problem location**\r\nClient, reader\r\n\r\n**Suggestions for an improvement**\r\nThe TAIL readers should not fail with `TruncatedDataException`. "},"comment":{"url":"https://api.github.com/repos/pravega/pravega/issues/comments/394790269","html_url":"https://github.com/pravega/pravega/issues/2664#issuecomment-394790269","issue_url":"https://api.github.com/repos/pravega/pravega/issues/2664","id":394790269,"node_id":"MDEyOklzc3VlQ29tbWVudDM5NDc5MDI2OQ==","user":{"login":"jkhalack","id":25368596,"node_id":"MDQ6VXNlcjI1MzY4NTk2","avatar_url":"https://avatars2.githubusercontent.com/u/25368596?v=4","gravatar_id":"","url":"https://api.github.com/users/jkhalack","html_url":"https://github.com/jkhalack","followers_url":"https://api.github.com/users/jkhalack/followers","following_url":"https://api.github.com/users/jkhalack/following{/other_user}","gists_url":"https://api.github.com/users/jkhalack/gists{/gist_id}","starred_url":"https://api.github.com/users/jkhalack/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/jkhalack/subscriptions","organizations_url":"https://api.github.com/users/jkhalack/orgs","repos_url":"https://api.github.com/users/jkhalack/repos","events_url":"https://api.github.com/users/jkhalack/events{/privacy}","received_events_url":"https://api.github.com/users/jkhalack/received_events","type":"User","site_admin":false},"created_at":"2018-06-05T17:16:38Z","updated_at":"2018-06-05T17:16:38Z","author_association":"COLLABORATOR","body":"Probably related to https://github.com/pravega/pravega/issues/2609 "}}
{"actor":{"display_login":"jkhalack"}}