{"action":"created","issue":{"url":"https://api.github.com/repos/real-logic/Aeron/issues/244","repository_url":"https://api.github.com/repos/real-logic/Aeron","labels_url":"https://api.github.com/repos/real-logic/Aeron/issues/244/labels{/name}","comments_url":"https://api.github.com/repos/real-logic/Aeron/issues/244/comments","events_url":"https://api.github.com/repos/real-logic/Aeron/issues/244/events","html_url":"https://github.com/real-logic/Aeron/issues/244","id":160806889,"number":244,"title":"Subscription intermittently stops delivering messages","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/enhancement","name":"enhancement","color":"84b6eb"}],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":21,"created_at":"2016-06-17T03:49:04Z","updated_at":"2016-06-24T02:58:08Z","closed_at":null,"body":"Hi, similar issue to #234, but with slightly different behaviour, so I'm raising a new issue.  One of the subscriptions on a specific channel causes all of the others to stall and results in back pressure on the publication.\r\n\r\nHere is AeronStat output for stream `-1762877036`.  Note registrationId `1167` is show a sub-pos much smaller than the others.\r\n\r\nAeronStat\r\n```\r\n983:               65,184 - pub-lmt: 853 880428294 -1762877036 aeron:udp?group=239.193.0.1:10000|interface=172.29.1.1\r\n984:               32,416 - snd-pos: 853 880428294 -1762877036 aeron:udp?group=239.193.0.1:10000|interface=172.29.1.1\r\n1099:               29,920 - sub-pos: 1428 880428294 -1762877036 aeron:udp?group=239.193.0.1:10000|interface=172.29.1.1\r\n1134:               29,920 - sub-pos: 460 880428294 -1762877036 aeron:udp?group=239.193.0.1:10000|interface=172.29.1.1\r\n1135:               29,920 - sub-pos: 428 880428294 -1762877036 aeron:udp?group=239.193.0.1:10000|interface=172.29.1.1\r\n1136:               29,920 - sub-pos: 309 880428294 -1762877036 aeron:udp?group=239.193.0.1:10000|interface=172.29.1.1\r\n1137:               29,920 - sub-pos: 241 880428294 -1762877036 aeron:udp?group=239.193.0.1:10000|interface=172.29.1.1\r\n1140:               29,920 - sub-pos: 197 880428294 -1762877036 aeron:udp?group=239.193.0.1:10000|interface=172.29.1.1\r\n1141:               29,920 - sub-pos: 76 880428294 -1762877036 aeron:udp?group=239.193.0.1:10000|interface=172.29.1.1\r\n1227:               29,920 - sub-pos: 1332 880428294 -1762877036 aeron:udp?group=239.193.0.1:10000|interface=172.29.1.1\r\n1435:               29,920 - sub-pos: 718 880428294 -1762877036 aeron:udp?group=239.193.0.1:10000|interface=172.29.1.1\r\n1436:               29,920 - sub-pos: 776 880428294 -1762877036 aeron:udp?group=239.193.0.1:10000|interface=172.29.1.1\r\n1437:                  384 - sub-pos: 1167 880428294 -1762877036 aeron:udp?group=239.193.0.1:10000|interface=172.29.1.1\r\n1438:               32,416 - rcv-hwm: 1270 880428294 -1762877036 aeron:udp?group=239.193.0.1:10000|interface=172.29.1.1\r\n1464:               29,920 - sub-pos: 1293 880428294 -1762877036 aeron:udp?group=239.193.0.1:10000|interface=172.29.1.1\r\n1712:               29,920 - sub-pos: 1962 880428294 -1762877036 aeron:udp?group=239.193.0.1:10000|interface=172.29.1.1\r\n1761:               29,920 - sub-pos: 1671 880428294 -1762877036 aeron:udp?group=239.193.0.1:10000|interface=172.29.1.1\r\n1973:               29,920 - sub-pos: 1836 880428294 -1762877036 aeron:udp?group=239.193.0.1:10000|interface=172.29.1.1\r\n2039:               29,920 - sub-pos: 1928 880428294 -1762877036 aeron:udp?group=239.193.0.1:10000|interface=172.29.1.1\r\n2060:               29,920 - sub-pos: 2038 880428294 -1762877036 aeron:udp?group=239.193.0.1:10000|interface=172.29.1.1\r\n```\r\n\r\nI have some custom monitoring of my handler so that I can track if this subscription is still being polled.  You can see the streamId and registrationId matches the problematic subscription and pollCount is increasing, which means I'm confident our polling code hasn't crashed.\r\n\r\n```\r\n$>bean com.lmax:name=tfx-group__InstrumentNotificationServicePublic,service=cfdx,type=AeronReceiver \r\n#bean is set to com.lmax:name=tfx-group__InstrumentNotificationServicePublic,service=cfdx,type=AeronReceiver\r\n$>get *\r\n#mbean = com.lmax:name=tfx-group__InstrumentNotificationServicePublic,service=cfdx,type=AeronReceiver:\r\nRegistrationId = 1167;\r\nTopicName = tfx-group::InstrumentNotificationServicePublic;\r\nStreamId = -1762877036;\r\nPollCount = 441575;\r\nUri = aeron:udp?group=239.193.0.1:10000|interface=172.29.1.1;\r\n\r\n$>get *\r\n#mbean = com.lmax:name=tfx-group__InstrumentNotificationServicePublic,service=cfdx,type=AeronReceiver:\r\nRegistrationId = 1167;\r\nTopicName = tfx-group::InstrumentNotificationServicePublic;\r\nStreamId = -1762877036;\r\nPollCount = 691272;\r\nUri = aeron:udp?group=239.193.0.1:10000|interface=172.29.1.1;\r\n```\r\n\r\nPolling code:\r\n\r\n        public int poll()\r\n        {\r\n            final int poll = subscription.poll(handler, 20);\r\n            ++pollCount;\r\n            return poll;\r\n        }\r\n\r\nLooking at the log inspect for the appropriate subscription image show that aeron thinks the term is unused and dirty.  I.e. the first show no messages, but has not been cleaned the remaining 2 terms are all zeros.  The LogInspector suggests that there are no messages in that term.\r\n\r\n```\r\n ======================================================================\r\n Fri Jun 17 03:38:17 UTC 2016 Inspection dump for /dev/shm/aeron-tradex/images/UDP-ac1d0101-0-efc10001-10000-347A4506-96ECA194-4F6.logbuffer\r\n ======================================================================\r\n Time of last SM: Thu Jan 01 00:00:00 UTC 1970\r\n Initial term id: -1970406852\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=880428294 stream_id=-1762877036 term_id=-1970406852 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 Index 0 Term Data\r\n\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 00000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000\r\n 00000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000\r\n 00000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000\r\n 00000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000\r\n 00000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000\r\n 00002C00000000C001008001000006457A3494A1EC963CFA8D8A0000000000000000000000080000000000000000000000000000000000000000000000000000000020000000\r\n 00C00100C001000006457A3494A1EC963CFA8D8A00000000000000002C00000000C00100E001000006457A3494A1EC963CFA8D8A000000000000000000000008000000000000\r\n ...\r\n```"},"comment":{"url":"https://api.github.com/repos/real-logic/Aeron/issues/comments/228246119","html_url":"https://github.com/real-logic/Aeron/issues/244#issuecomment-228246119","issue_url":"https://api.github.com/repos/real-logic/Aeron/issues/244","id":228246119,"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-24T02:58:08Z","updated_at":"2016-06-24T02:58:08Z","body":"I've run the 0.9.9-SNAPSHOT version through our CI system and I get the same sort of failure.\r\n\r\nAeronStat:\r\n```\r\n02:35:40 - Aeron Stat\r\n=========================\r\n  0:           94,747,936 - Bytes sent\r\n  1:           97,622,944 - 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:               37,100 - NAKs sent\r\n  6:               37,100 - NAKs received\r\n  7:            1,393,407 - Status Messages sent\r\n  8:            1,393,634 - Status Messages received\r\n  9:            2,696,965 - Heartbeats sent\r\n 10:            2,472,784 - Heartbeats received\r\n 11:               11,251 - Retransmits sent\r\n 12:                1,158 - 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:               55,230 - Client keep-alives\r\n 18:                  433 - 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\r\n1306:               65,792 - pub-lmt: 896 926135193 -1762877036 aeron:udp?endpoint=239.193.0.1:10000|interface=172.29.1.1 \r\n 1307:               33,024 - snd-pos: 896 926135193 -1762877036 aeron:udp?endpoint=239.193.0.1:10000|interface=172.29.1.1 \r\n 1480:               33,024 - sub-pos: 76 926135193 -1762877036 aeron:udp?endpoint=239.193.0.1:10000|interface=172.29.1.1 @576\r\n 1481:               33,024 - sub-pos: 201 926135193 -1762877036 aeron:udp?endpoint=239.193.0.1:10000|interface=172.29.1.1 @576\r\n 1482:               33,024 - sub-pos: 265 926135193 -1762877036 aeron:udp?endpoint=239.193.0.1:10000|interface=172.29.1.1 @576\r\n 1483:               33,024 - sub-pos: 302 926135193 -1762877036 aeron:udp?endpoint=239.193.0.1:10000|interface=172.29.1.1 @576\r\n 1484:               33,024 - sub-pos: 379 926135193 -1762877036 aeron:udp?endpoint=239.193.0.1:10000|interface=172.29.1.1 @576\r\n 1485:               33,024 - sub-pos: 491 926135193 -1762877036 aeron:udp?endpoint=239.193.0.1:10000|interface=172.29.1.1 @576\r\n 1486:               33,024 - sub-pos: 711 926135193 -1762877036 aeron:udp?endpoint=239.193.0.1:10000|interface=172.29.1.1 @576\r\n 1487:               33,024 - sub-pos: 770 926135193 -1762877036 aeron:udp?endpoint=239.193.0.1:10000|interface=172.29.1.1 @576\r\n 1488:                  576 - sub-pos: 1136 926135193 -1762877036 aeron:udp?endpoint=239.193.0.1:10000|interface=172.29.1.1 @576\r\n 1489:               33,024 - rcv-hwm: 1182 926135193 -1762877036 aeron:udp?endpoint=239.193.0.1:10000|interface=172.29.1.1 \r\n 1490:               33,024 - rcv-pos: 1182 926135193 -1762877036 aeron:udp?endpoint=239.193.0.1:10000|interface=172.29.1.1 \r\n 1513:               33,024 - sub-pos: 1207 926135193 -1762877036 aeron:udp?endpoint=239.193.0.1:10000|interface=172.29.1.1 @24,160\r\n 1578:               33,024 - sub-pos: 1261 926135193 -1762877036 aeron:udp?endpoint=239.193.0.1:10000|interface=172.29.1.1 @24,256\r\n 1906:               33,024 - sub-pos: 1492 926135193 -1762877036 aeron:udp?endpoint=239.193.0.1:10000|interface=172.29.1.1 @33,024\r\n 2090:               33,024 - sub-pos: 1639 926135193 -1762877036 aeron:udp?endpoint=239.193.0.1:10000|interface=172.29.1.1 @33,024\r\n 2217:               33,024 - sub-pos: 1745 926135193 -1762877036 aeron:udp?endpoint=239.193.0.1:10000|interface=172.29.1.1 @33,024\r\n 2332:               33,024 - sub-pos: 1848 926135193 -1762877036 aeron:udp?endpoint=239.193.0.1:10000|interface=172.29.1.1 @33,024\r\n 2360:               33,024 - sub-pos: 1875 926135193 -1762877036 aeron:udp?endpoint=239.193.0.1:10000|interface=172.29.1.1 @33,024\r\n 2391:               33,024 - sub-pos: 1913 926135193 -1762877036 aeron:udp?endpoint=239.193.0.1:10000|interface=172.29.1.1 @33,024\r\n```\r\n\r\nThe log buffer data ([aeron-buffer.zip](https://github.com/real-logic/Aeron/files/331136/aeron-buffer.zip)) is also available.\r\n\r\nIs there any other data that would be useful to capture?\r\n\r\n"}}
{"actor":{"display_login":"mikeb01"}}