We get the QueryIteratorCheck messages when the system has become heavily loaded. That suggested to me that when a timeout cancels the request, the cancellation code calls a close() that doesn't close the underlying iterator. But I will go and have another look.
It's definitely more subtle that I had thought ... Chris On 16 March 2017 at 17:08, Andy Seaborne <a...@apache.org> wrote: > > > On 16/03/17 15:47, Chris Dollin wrote: > >> (Was offline yesterday) >> >> Similar in result, at least. Having SortedBindingIterator.close() >> close the underlying iterator -- which at this point should be >> empty since it's been the source of the bindings to sort -- should >> be harmless, and ensure that that iterator /does/ get closed. >> > > It may not have started. > > What is unclear is why you get the log message when it isn't happening > more generally. > > Andy > > > >> What I'm not sure of is whether there's some reason that >> SortedBindingIterator should /not/ close the underlying >> iterator, to fit in with the close/closIterator protocol. >> >> Any suggestions? >> >> Chris >> >> >> >> On 15 March 2017 at 13:04, Andy Seaborne <a...@apache.org> wrote: >> >> Similar to JENA-1298? >>> >>> >>> >>> On 15/03/17 07:55, Chris Dollin wrote: >>> >>> Dear All >>>> >>>> We think we've spotted a bug in ARQs SortedDataBag. >>>> During operation of our Fuseki servers (we're running >>>> Fuseki 2.4.1 wi. with timeouts) we saw log entries >>>> of the form >>>> >>>> WARN QueryIteratorCheck :: Open iterator: >>>> QueryIterOptionalIndex/- >>>> 1454412710 >>>> >>>> for (some, intermitent) queries with sorting. >>>> >>>> Exploring the code found something suggestive in >>>> >>>> QueryIterSort.SortedBindingIterator >>>> >>>> which takes as a constructor parameter qIter, and >>>> keeps as a like-named instance variable, the iterator >>>> whose content is to be sorted. It's close() method >>>> closes the data bag but /not/ the underlying qIter. >>>> >>>> If SortedBindingIterator.initializeIterator() pulls >>>> all of the items from qIter into the databag, >>>> it will auto-close that iterator. If initialization >>>> runs to completion, closing the sorted binding >>>> iterator will /not/ close that iterator. So whether >>>> it is closed will depend on how loaded Fuseki >>>> is. >>>> >>>> We verified that under normal (non-cancelled) circumstances >>>> closing a SortedBindingIterator did not close the >>>> underlying iterator (qIter, above) by tweaking >>>> TestQueryIterSort.testCleanAfterCode to check that >>>> after QueryIterSort iterator has been closed its >>>> underlying iterator has also been closed. (This >>>> required making TestQueryIterSort.iterator public.) >>>> This modified test fails, as we'd expect. >>>> >>>> Making SortedBindingIterator.close() perform qIter.close() >>>> makes the modified test pass, again as we'd expect? >>>> >>>> So. >>>> >>>> Is the non-closing behaviour of SortedBindingIterator intended >>>> or is it, as we think, a fixable bug? I'm happy to raise a JIRA >>>> if that's appropriate and provide a pull request. >>>> >>>> Chris >>>> >>>> >>>> >>
