{"action":"created","issue":{"url":"https://api.github.com/repos/real-logic/Aeron/issues/234","repository_url":"https://api.github.com/repos/real-logic/Aeron","labels_url":"https://api.github.com/repos/real-logic/Aeron/issues/234/labels{/name}","comments_url":"https://api.github.com/repos/real-logic/Aeron/issues/234/comments","events_url":"https://api.github.com/repos/real-logic/Aeron/issues/234/events","html_url":"https://github.com/real-logic/Aeron/issues/234","id":158284808,"number":234,"title":"Intermittently Message Flow on Some Streams Appears to Stop","user":{"login":"mikeb01","id":309215,"avatar_url":"https://avatars.githubusercontent.com/u/309215?v=3","gravatar_id":"","url":"https://api.github.com/users/mikeb01","html_url":"https://github.com/mikeb01","followers_url":"https://api.github.com/users/mikeb01/followers","following_url":"https://api.github.com/users/mikeb01/following{/other_user}","gists_url":"https://api.github.com/users/mikeb01/gists{/gist_id}","starred_url":"https://api.github.com/users/mikeb01/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/mikeb01/subscriptions","organizations_url":"https://api.github.com/users/mikeb01/orgs","repos_url":"https://api.github.com/users/mikeb01/repos","events_url":"https://api.github.com/users/mikeb01/events{/privacy}","received_events_url":"https://api.github.com/users/mikeb01/received_events","type":"User","site_admin":false},"labels":[{"url":"https://api.github.com/repos/real-logic/Aeron/labels/bug","name":"bug","color":"fc2929"},{"url":"https://api.github.com/repos/real-logic/Aeron/labels/question","name":"question","color":"cc317c"}],"state":"open","locked":false,"assignee":null,"milestone":null,"comments":10,"created_at":"2016-06-03T03:36:05Z","updated_at":"2016-06-13T03:42:48Z","closed_at":null,"body":"Within our system sometimes one of our streams stops moving messages from the publication to the image.  We have a single media driver on one machine with 43 processes and ~400 streams running.  I am running with small terms (64K) as this is a resource constrained acceptance test system.  This manifests as one of the channels continually reporting \"BACK_PRESSURED (-2)\" on offer.  Digging with AeronStat I see the following for stream 669.\r\n\r\n```\r\n834:              112,224 - snd-pos: 910 -436124807 669 aeron:udp?group=239.193.0.1:10000|interface=172.29.1.1\r\n835:              144,992 - pub-lmt: 910 -436124807 669 aeron:udp?group=239.193.0.1:10000|interface=172.29.1.1\r\n1078:               47,136 - sub-pos: 86 -436124807 669 aeron:udp?group=239.193.0.1:10000|interface=172.29.1.1\r\n1079:               47,136 - sub-pos: 213 -436124807 669 aeron:udp?group=239.193.0.1:10000|interface=172.29.1.1\r\n1080:               47,136 - sub-pos: 259 -436124807 669 aeron:udp?group=239.193.0.1:10000|interface=172.29.1.1\r\n1081:               47,136 - sub-pos: 301 -436124807 669 aeron:udp?group=239.193.0.1:10000|interface=172.29.1.1\r\n1082:               47,136 - sub-pos: 344 -436124807 669 aeron:udp?group=239.193.0.1:10000|interface=172.29.1.1\r\n1083:               47,136 - sub-pos: 669 -436124807 669 aeron:udp?group=239.193.0.1:10000|interface=172.29.1.1\r\n1084:               47,136 - sub-pos: 733 -436124807 669 aeron:udp?group=239.193.0.1:10000|interface=172.29.1.1\r\n1085:               47,136 - sub-pos: 813 -436124807 669 aeron:udp?group=239.193.0.1:10000|interface=172.29.1.1\r\n1086:              112,224 - rcv-hwm: 1049 -436124807 669 aeron:udp?group=239.193.0.1:10000|interface=172.29.1.1\r\n1200:               47,136 - sub-pos: 1170 -436124807 669 aeron:udp?group=239.193.0.1:10000|interface=172.29.1.1\r\n1217:               47,136 - sub-pos: 1186 -436124807 669 aeron:udp?group=239.193.0.1:10000|interface=172.29.1.1\r\n1325:               47,136 - sub-pos: 1293 -436124807 669 aeron:udp?group=239.193.0.1:10000|interface=172.29.1.1\r\n1525:               47,136 - sub-pos: 1468 -436124807 669 aeron:udp?group=239.193.0.1:10000|interface=172.29.1.1\r\n1695:               47,136 - sub-pos: 1649 -436124807 669 aeron:udp?group=239.193.0.1:10000|interface=172.29.1.1\r\n1799:               47,136 - sub-pos: 1755 -436124807 669 aeron:udp?group=239.193.0.1:10000|interface=172.29.1.1\r\n1888:               47,136 - sub-pos: 1855 -436124807 669 aeron:udp?group=239.193.0.1:10000|interface=172.29.1.1\r\n1918:               47,136 - sub-pos: 1886 -436124807 669 aeron:udp?group=239.193.0.1:10000|interface=172.29.1.1\r\n1938:               47,136 - sub-pos: 1921 -436124807 669 aeron:udp?group=239.193.0.1:10000|interface=172.29.1.1\r\n```\r\n\r\nThe sender (there is only one is this set up) is published up to 112,224 where as all of the subscriptions have stopped at 47,136.  Looking at the system counters of AeronStat I can see a large number of NAKs and some flow control under flow events.\r\n\r\n```\r\n03:12:02 - Aeron Stat\r\n=========================\r\n  0:            3,668,480 - Bytes Sent\r\n  1:           52,288,224 - Bytes received\r\n  2:                    0 - Failed offers to ReceiverProxy\r\n  3:                    0 - Failed offers to SenderProxy\r\n  4:                    0 - Failed offers to DriverConductorProxy\r\n  5:               41,619 - NAKs sent\r\n  6:               41,615 - NAKs received\r\n  7:              721,434 - Status Messages sent\r\n  8:              721,921 - Status Messages received\r\n  9:            1,399,492 - Heartbeats sent\r\n 10:            1,195,703 - Heartbeats received\r\n 11:               13,923 - Retransmits sent\r\n 12:                  433 - Flow control under runs\r\n 13:                    0 - Flow control over runs\r\n 14:                    0 - Invalid packets\r\n 15:                    0 - Errors\r\n 16:                    0 - Short sends\r\n 17:               29,824 - Client keep-alives\r\n 18:                  425 - Sender flow control limits applied\r\n 19:                    0 - Unblocked Publications\r\n 20:                    0 - Unblocked Control Commands\r\n 21:                    0 - Possible TTL Asymmetry\r\n 22:                    1 - send-channel: aeron:udp?group=239.193.0.1:10000|interface=172.29.1.1\r\n```\r\n\r\nIt would be useful of some of these counters could be reported against their specific streams (I've raised enhancement #233 to cover this).  If use the LogInspector, I can see that the Image does not have any messages beyond the sub-pos (43,136).\r\n\r\n```\r\n ======================================================================\r\n Fri Jun 03 03:21:08 UTC 2016 Inspection dump for /dev/shm/aeron-tradex/images/UDP-ac1d0101-0-efc10001-10000-E6014379-29D-419.logbuffer\r\n ======================================================================\r\n Time of last SM: Thu Jan 01 00:00:00 UTC 1970\r\n Initial term id: 1723865762\r\n    Active index: 0\r\n     Term length: 65536\r\n      MTU length: 4096\r\n\r\n default Data Header{frame_length=0 version=0 flags=11000000 type=1 frame_length=0 term_offset=0 session_id=-436124807 stream_id=669 term_id=1723865762 reserved_value=0}\r\n\r\n Index 0 Term Meta Data status=CLEAN termOffset=0 termId=0\r\n Index 1 Term Meta Data status=CLEAN termOffset=0 termId=0\r\n Index 2 Term Meta Data status=CLEAN termOffset=0 termId=0\r\n %n======================================================================\r\n\r\n...\r\n\r\n Data Header{frame_length=32 version=0 flags=11000000 type=1 frame_length=32 term_offset=46336 session_id=-436124807 stream_id=669 term_id=1723865762 reserved_value=0}\r\n\r\n Data Header{frame_length=762 version=0 flags=11000000 type=1 frame_length=762 term_offset=46368 session_id=-436124807 stream_id=669 term_id=1723865762 reserved_value=0}\r\n 000002D6000000000000003A00FFFFFFFFFFFFFFFF0000006D6400000000000002BF00000000000002BF00000000000002BF00000000000002BF00000001000000120042002D006C006100620065006C00200069\r\n 006E0073007400720075006D0065006E007400006D650000753A0000011E3ECF000000000000000000010A0000000000000001070000000000000001010000000000006DBF00006DBE004E00006DC00055000000\r\n 000300470042005000000001010000000200000001010000000100000001000000000000000002138800000000000000003B9ACA00FFFFFFFF000000016400000000000000016400000000000000030037003000\r\n 3300000000000003EA000000030186A000000003000000030186A000000003FFFFFFFFFFFFFFFFFFFFFFFF00006D7200006D730000000F00440065006600610075006C007400430061006C0065006E0064006100\r\n 720000755C0000000D004500750072006F00700065002F004C006F006E0064006F006E0000000700006D740000006D740100006D740200006D740300006D740400006D740500006D74060000755A000000000000\r\n 00000000755A0000000005265C0000000000000000010000000F00440065006600610075006C007400430061006C0065006E00640061007200006D7D00000000000000000000000000006D6E00000000000003EC\r\n 00006D6F000000050049004E004400450058000000120042002D006C006100620065006C00200069006E0073007400720075006D0065006E007400000003003100320036000000000000016D000000050050004F\r\n 0049004E005400006DB7000000016400000002FFFFFFFF00006D780000000100000000020000000100000000020000001100310020006D006F006E0074006800200047004200500020004C00490042004F0052FF\r\n FFFFFFFFFFFFFFFFFFFFFF000000010000006D66000000010000000002FFFFFFFF00000000000000000000000000000000010000000500000036\r\n Data Header{frame_length=0 version=0 flags=00000000 type=0 frame_length=0 term_offset=0 session_id=0 stream_id=0 term_id=0 reserved_value=0}\r\n 000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000\r\n 000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000\r\n```\r\n\r\nInterestingly If I look at the associated publication, then is appears that the messages that should be in that term look like they have already been cleaned as the term at index 0 (term_id=1723865762) contains nothing but a padding record.\r\n\r\n```\r\n ======================================================================\r\nFri Jun 03 03:19:14 UTC 2016 Inspection dump for /dev/shm/aeron-tradex/publications/UDP-ac1d0101-0-efc10001-10000-E6014379-29D-38E.logbuffer\r\n======================================================================\r\nTime of last SM: Fri Jun 03 03:15:56 UTC 2016\r\nInitial term id: 1723865762\r\n   Active index: 2\r\n    Term length: 65536\r\n     MTU length: 4096\r\n\r\ndefault Data Header{frame_length=0 version=0 flags=11000000 type=1 frame_length=0 term_offset=0 session_id=-436124807 stream_id=669 term_id=1723865762 reserved_value=0}\r\n\r\nIndex 0 Term Meta Data status=CLEAN termOffset=65920 termId=1723865762\r\nIndex 1 Term Meta Data status=CLEAN termOffset=65760 termId=1723865763\r\nIndex 2 Term Meta Data status=CLEAN termOffset=14144 termId=1723865764\r\n%n======================================================================\r\nIndex 0 Term Data\r\n\r\nData Header{frame_length=0 version=0 flags=00000000 type=0 frame_length=0 term_offset=0 session_id=0 stream_id=0 term_id=0 reserved_value=0}\r\n00000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000\r\n00000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000\r\n...\r\n00000000000000000000000000000000000000\r\n%n======================================================================\r\nIndex 1 Term Data\r\n\r\nData Header{frame_length=726 version=0 flags=11000000 type=1 frame_length=726 term_offset=0 session_id=-436124807 stream_id=669 term_id=1723865763 reserved_value=0}\r\n000002B2000000000000005200FFFFFFFFFFFFFFFF0000006D6400000000000002D900000000000002D900000000000002D900000000000002D900000001000000090050006100670069006E006700200031003\r\n900006D650000753A0000011E3ECF000000000000000000010A0000000000000001070000000000000001010000000000006DBF00006DBE004E00006DC000550000000003004700420050000000010100000002\r\n00000001010000000100000001000000000000000002138800000000000000003B9ACA00FFFFFFFF0000000164000000000000000164000000000000000300370032003900000000000003EA000000030186A0000\r\n00003000000030186A000000003FFFFFFFFFFFFFFFFFFFFFFFF00006D7200006D730000000F00440065006600610075006C007400430061006C0065006E0064006100720000755C0000000D004500750072006\r\nF00700065002F004C006F006E0064006F006E0000000700006D740000006D740100006D740200006D740300006D740400006D740500006D74060000755A00000000000000000000755A0000000005265C000000\r\n0000000000010000000F00440065006600610075006C007400430061006C0065006E00640061007200006D7D00000000000000000000000000006D6E00000000000003E900006D6F000000050049004E0044004\r\n50058000000090050006100670069006E006700200031003900000003003100320033000000000000016D000000050050004F0049004E005400006DB7000000016400000002FFFFFFFF00006D780000000100000\r\n000020000000100000000020000001100310020006D006F006E0074006800200047004200500020004C00490042004F0052FFFFFFFFFFFFFFFFFFFFFFFF000000010000006D66000000010000000002FFFFFFFF\r\n00000000000000000000000000000000010000001D00000036\r\n```"},"comment":{"url":"https://api.github.com/repos/real-logic/Aeron/issues/comments/225483688","html_url":"https://github.com/real-logic/Aeron/issues/234#issuecomment-225483688","issue_url":"https://api.github.com/repos/real-logic/Aeron/issues/234","id":225483688,"user":{"login":"mikeb01","id":309215,"avatar_url":"https://avatars.githubusercontent.com/u/309215?v=3","gravatar_id":"","url":"https://api.github.com/users/mikeb01","html_url":"https://github.com/mikeb01","followers_url":"https://api.github.com/users/mikeb01/followers","following_url":"https://api.github.com/users/mikeb01/following{/other_user}","gists_url":"https://api.github.com/users/mikeb01/gists{/gist_id}","starred_url":"https://api.github.com/users/mikeb01/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/mikeb01/subscriptions","organizations_url":"https://api.github.com/users/mikeb01/orgs","repos_url":"https://api.github.com/users/mikeb01/repos","events_url":"https://api.github.com/users/mikeb01/events{/privacy}","received_events_url":"https://api.github.com/users/mikeb01/received_events","type":"User","site_admin":false},"created_at":"2016-06-13T03:42:48Z","updated_at":"2016-06-13T03:42:48Z","body":"Didn't get a chance to test this week, will test again this Friday hopefully."}}
{"actor":{"display_login":"mikeb01"}}