Found the cause and I hate log4j...

Log4j was unable to find it's configuration file so was quietly defaulting
the RootLogger to debug. So when static public final Logger log =
LoggerFactory.getLogger(ReorderTransformationSubstitution.class) was called
it's parent is RootLogger and it's level is debug. So private final boolean
DEBUG = log.isDebugEnabled() sets DEBUG to true and under concurrent load
the exception is thrown.

I only found this because I set -Dlog4j.debug to see what was happening
because the logger level gets set "magically" (i.e. Eclipse IDE triggers a
breakpoint on the variable change seemingly randomly) after initialisation,
presumably because there's some delayed code run when the log4j framework
is touched.

The issue is repeatable without the log4j configuration but "fixed"
with -Dlog4j.configuration=file:///{path to configuration
file}/log4j.properties

Is it worth noting this behaviour somewhere?

Thanks for the point in the right direction.

Dick.

On 17 October 2016 at 21:33, Andy Seaborne <a...@apache.org> wrote:

>
>
> On 17/10/16 21:13, Dick Murray wrote:
>
>> Hi.
>>
>> On 17 Oct 2016 18:16, "Andy Seaborne" <a...@apache.org> wrote:
>>
>>>
>>> Are you running with debug tracing on?
>>>
>>
>> No, should I and what should I look for..?
>>
>
> I asked because that point in the code ...
>
>
> >>>      [java] org.apache.jena.atlas.iterator
> .Iter.asString(Iter.java:479)
> >>>      [java]
> >>>
> > org.apache.jena.sparql.engine.optimizer.reorder.ReorderTrans
> formationSubstitution.reorder(ReorderTransformationSubstitution.java:85)
> >>>
>
> Object field:
> private final boolean DEBUG = log.isDebugEnabled() ;
>
> then line 85:
>
>  if ( DEBUG )
>    log.debug("Reorder: "+Iter.asString(components, formatter)) ;
>
> The formatter is, mistakenly, shared because it an object field.
>
> But to get there, DEBUG has to be true.
>
> So it seems log.isDebugEnabled() is true.
>
>         Andy
>
>
>
>
>
>>
>>>     Andy
>>>
>>>
>>> On 17/10/16 11:30, Dick Murray wrote:
>>>
>>>>
>>>> Hi.
>>>>
>>>> I'm getting odd behaviour in Jena when I execute the same query
>>>> concurrently.
>>>>
>>>> The query has an optional which is unmatched but which appears to cause
>>>> a
>>>> java.lang.String exception from the atlas code.
>>>>
>>>> This only happens if multiple queries are submitted concurrently and
>>>> closely. On a "fast" host both queries will typically fail but on a
>>>>
>>> slower
>>
>>> host (VirtualBox with throttled cpu) the first query will return but the
>>>> second will fail.
>>>>
>>>> If I siege with 10 threads and a random delay of 2 seconds some queries
>>>> will succeed. Which makes it seem like a timing issue.
>>>>
>>>> The crux appears to be the optional, remove it and I can siege (10
>>>>
>>> threads,
>>
>>> 50 iterations) without any issues, with the optional I get exceptions.
>>>>
>>>> I originally thought it was the application/json format but returning
>>>> text/plain causes the exception and the root cause appears to be
>>>>
>>> something
>>
>>> in the atlas code passing in the wrong index to create a new String.
>>>>
>>>> To test if I run (Ubuntu 16.04 desktop) i.e. the same query concurrently
>>>> twice;
>>>>
>>>> wget -O q1 --header "accept: text/plain" "
>>>> http://localhost:8080/tdb/sparql?query=PREFIX dxf: <urn:iungo:dxf/>
>>>>
>>> SELECT
>>
>>> * WHERE { GRAPH
>>>>
>>> <urn:iungo:dxf/graph/309ea4ce-dbdf-4d92-9828-1d99d35d0bb4>
>>
>>> { { ?equipment dxf:attribute ?attribute  } . OPTIONAL {
>>>> ?tier_two_containment dxf:no_such_property ?equipment ;
>>>> dxf:still_no_such_property ?department_area }}}" & wget -O q2 --header
>>>> "accept: text/plain" "http://localhost:8080/tdb/sparql?query=PREFIX
>>>> dxf:
>>>> <urn:iungo:dxf/> SELECT * WHERE { GRAPH
>>>> <urn:iungo:dxf/graph/309ea4ce-dbdf-4d92-9828-1d99d35d0bb4> { {
>>>> ?equipment
>>>> dxf:attribute ?attribute  } . OPTIONAL { ?tier_two_containment
>>>> dxf:no_such_property ?equipment ; dxf:still_no_such_property
>>>> ?department_area }}}"
>>>>
>>>>
>>>> the q1 output will show the correct result but q2 will either be 0 bytes
>>>>
>>> or
>>
>>> truncated and the following exception is show.
>>>>
>>>> dick@Dick-M3800:/media/dick/Backup1/bc$ wget -O q1 --header "accept:
>>>> text/plain" "http://localhost:8080/tdb/sparql?query=PREFIX dxf:
>>>> <urn:iungo:dxf/> SELECT * WHERE { GRAPH
>>>> <urn:iungo:dxf/graph/309ea4ce-dbdf-4d92-9828-1d99d35d0bb4> { {
>>>> ?equipment
>>>> dxf:attribute ?attribute  } . OPTIONAL { ?tier_two_containment
>>>> dxf:no_such_property ?equipment ; dxf:still_no_such_property
>>>> ?department_area }}}" & wget -O q2 --header "accept: text/plain" "
>>>> http://localhost:8080/tdb/sparql?query=PREFIX dxf: <urn:iungo:dxf/>
>>>>
>>> SELECT
>>
>>> * WHERE { GRAPH
>>>>
>>> <urn:iungo:dxf/graph/309ea4ce-dbdf-4d92-9828-1d99d35d0bb4>
>>
>>> { { ?equipment dxf:attribute ?attribute  } . OPTIONAL {
>>>> ?tier_two_containment dxf:no_such_property ?equipment ;
>>>> dxf:still_no_such_property ?department_area }}}"
>>>> [1] 7594
>>>> --2016-10-17 11:03:21--
>>>>
>>>> http://localhost:8080/tdb/sparql?query=PREFIX%20dxf:%20%3Cur
>> n:iungo:dxf/%3E%20SELECT%20*%20WHERE%20%7B%20GRAPH%20%3Curn
>> :iungo:dxf/graph/309ea4ce-dbdf-4d92-9828-1d99d35d0bb4%
>> 3E%20%7B%20%7B%20?equipment%20dxf:attribute%20?attribute%
>> 20%20%7D%20.%20OPTIONAL%20%7B%20?tier_two_containment%20dxf:
>> no_such_property%20?equipment%20;%20dxf:still_no_such_
>> property%20?department_area%20%7D%7D%7D
>>
>>> Resolving localhost (localhost)... --2016-10-17 11:03:21--
>>>>
>>>> http://localhost:8080/tdb/sparql?query=PREFIX%20dxf:%20%3Cur
>> n:iungo:dxf/%3E%20SELECT%20*%20WHERE%20%7B%20GRAPH%20%3Curn
>> :iungo:dxf/graph/309ea4ce-dbdf-4d92-9828-1d99d35d0bb4%
>> 3E%20%7B%20%7B%20?equipment%20dxf:attribute%20?attribute%
>> 20%20%7D%20.%20OPTIONAL%20%7B%20?tier_two_containment%20dxf:
>> no_such_property%20?equipment%20;%20dxf:still_no_such_
>> property%20?department_area%20%7D%7D%7D
>>
>>> Resolving localhost (localhost)... 127.0.0.1127.0.0.1
>>>>
>>>> Connecting to localhost (localhost)|127.0.0.1|:8080... Connecting to
>>>> localhost (localhost)|127.0.0.1|:8080... connected.
>>>> connected.
>>>> HTTP request sent, awaiting response... HTTP request sent, awaiting
>>>> response... 200 OK
>>>> 200 OK
>>>> Length: Length: 00 [text/plain]
>>>>  [text/plain]
>>>> Saving to: ‘q1’
>>>> Saving to: ‘q2’
>>>>
>>>>
>>>> q1                                          [ <=>
>>>>                                                  ]       0  --.-KB/s
>>>>
>>> in
>>
>>> 0s
>>>>
>>>> q2                                          [ <=>
>>>>                                                  ]       0  --.-KB/s
>>>>
>>> in
>>
>>> 0s
>>>>
>>>> 2016-10-17 11:03:22 (0.00 B/s) - ‘q1’ saved [0/0]
>>>>
>>>> 2016-10-17 11:03:22 (0.00 B/s) - ‘q2’ saved [0/0]
>>>>
>>>>
>>>> and an exception is thrown from java.lang.String
>>>>
>>>> Exception java.lang.StringIndexOutOfBoundsException: String index out
>>>> of
>>>> range: 247
>>>>      [java] java.lang.String.<init>(String.java:205)
>>>>      [java] java.lang.StringBuilder.toString(StringBuilder.java:407)
>>>>      [java]
>>>>
>>> org.apache.jena.atlas.iterator.AccString.get(AccString.java:52)
>>
>>>      [java]
>>>>
>>> org.apache.jena.atlas.iterator.AccString.get(AccString.java:21)
>>
>>>      [java] org.apache.jena.atlas.iterator.Iter.reduce(Iter.java:165)
>>>>      [java] org.apache.jena.atlas.iterator.Iter.asString(Iter.java:483)
>>>>      [java] org.apache.jena.atlas.iterator.Iter.asString(Iter.java:479)
>>>>      [java]
>>>>
>>>> org.apache.jena.sparql.engine.optimizer.reorder.ReorderTrans
>> formationSubstitution.reorder(ReorderTransformationSubstitution.java:85)
>>
>>>      [java]
>>>>
>>>> org.apache.jena.sparql.engine.optimizer.reorder.ReorderTrans
>> formationSubstitution.reorderIndexes(ReorderTransfor
>> mationSubstitution.java:69)
>>
>>>      [java]
>>>>
>>>> org.apache.jena.tdb.solver.OpExecutorTDB1.reorder(OpExecutor
>> TDB1.java:276)
>>
>>>      [java]
>>>>
>>>> org.apache.jena.tdb.solver.OpExecutorTDB1.optimizeExecuteQua
>> ds(OpExecutorTDB1.java:230)
>>
>>>      [java]
>>>>
>>>> org.apache.jena.tdb.solver.OpExecutorTDB1.execute(OpExecutor
>> TDB1.java:148)
>>
>>>      [java]
>>>>
>>>> org.apache.jena.sparql.engine.main.ExecutionDispatch.visit(E
>> xecutionDispatch.java:66)
>>
>>>      [java]
>>>>
>>>> org.apache.jena.sparql.algebra.op.OpQuadPattern.visit(
>> OpQuadPattern.java:95)
>>
>>>      [java]
>>>>
>>>> org.apache.jena.sparql.engine.main.ExecutionDispatch.exec(Ex
>> ecutionDispatch.java:46)
>>
>>>      [java]
>>>> org.apache.jena.sparql.engine.main.OpExecutor.exec(OpExecutor.java:118)
>>>>      [java]
>>>> org.apache.jena.tdb.solver.OpExecutorTDB1.exec(OpExecutorTDB1.java:87)
>>>>      [java]
>>>> org.apache.jena.sparql.engine.main.OpExecutor.execute(OpExec
>>>> utor.java:89)
>>>>      [java] org.apache.jena.sparql.engine.main.QC.execute(QC.java:52)
>>>>      [java]
>>>>
>>>> org.apache.jena.sparql.engine.main.iterator.QueryIterOptiona
>> lIndex.nextStage(QueryIterOptionalIndex.java:51)
>>
>>>      [java]
>>>>
>>>> org.apache.jena.sparql.engine.iterator.QueryIterRepeatApply.
>> makeNextStage(QueryIterRepeatApply.java:108)
>>
>>>      [java]
>>>>
>>>> org.apache.jena.sparql.engine.iterator.QueryIterRepeatApply.
>> hasNextBinding(QueryIterRepeatApply.java:65)
>>
>>>      [java]
>>>>
>>>> org.apache.jena.sparql.engine.iterator.QueryIteratorBase.has
>> Next(QueryIteratorBase.java:111)
>>
>>>      [java]
>>>>
>>>> org.apache.jena.sparql.engine.iterator.QueryIteratorWrapper.
>> hasNextBinding(QueryIteratorWrapper.java:39)
>>
>>>      [java]
>>>>
>>>> org.apache.jena.sparql.engine.iterator.QueryIteratorBase.has
>> Next(QueryIteratorBase.java:111)
>>
>>>      [java]
>>>>
>>>> org.apache.jena.sparql.engine.iterator.QueryIteratorWrapper.
>> hasNextBinding(QueryIteratorWrapper.java:39)
>>
>>>      [java]
>>>>
>>>> org.apache.jena.sparql.engine.iterator.QueryIteratorBase.has
>> Next(QueryIteratorBase.java:111)
>>
>>>      [java]
>>>>
>>>> org.apache.jena.sparql.engine.iterator.QueryIteratorWrapper.
>> hasNextBinding(QueryIteratorWrapper.java:39)
>>
>>>      [java]
>>>>
>>>> org.apache.jena.sparql.engine.iterator.QueryIteratorBase.has
>> Next(QueryIteratorBase.java:111)
>>
>>>      [java]
>>>>
>>>> org.apache.jena.sparql.engine.ResultSetStream.hasNext(Result
>> SetStream.java:74)
>>
>>>      [java]
>>>>
>>>> org.apache.jena.sparql.engine.ResultSetCheckCondition.hasNex
>> t(ResultSetCheckCondition.java:59)
>>
>>>      [java]
>>>>
>>>> org.apache.jena.sparql.resultset.ResultSetMem.<init>(ResultS
>> etMem.java:86)
>>
>>>      [java]
>>>>
>>>> org.apache.jena.query.ResultSetFactory.makeRewindable(Result
>> SetFactory.java:404)
>>
>>>      [java]
>>>> org.apache.jena.sparql.resultset.TextOutput.write(TextOutput.java:145)
>>>>      [java]
>>>> org.apache.jena.sparql.resultset.TextOutput.write(TextOutput.java:130)
>>>>      [java]
>>>> org.apache.jena.sparql.resultset.TextOutput.write(TextOutput.java:118)
>>>>      [java]
>>>> org.apache.jena.sparql.resultset.TextOutput.format(TextOutput.java:66)
>>>>
>>>>
>>>> However if I run;
>>>>
>>>> wget -O q1 --header "accept: text/plain" "
>>>> http://localhost:8080/tdb/sparql?query=PREFIX dxf: <urn:iungo:dxf/>
>>>>
>>> SELECT
>>
>>> * WHERE { GRAPH
>>>>
>>> <urn:iungo:dxf/graph/309ea4ce-dbdf-4d92-9828-1d99d35d0bb4>
>>
>>> { { ?equipment dxf:attribute ?attribute  } . }}" & wget -O q2 --header
>>>> "accept: text/plain" "http://localhost:8080/tdb/sparql?query=PREFIX
>>>> dxf:
>>>> <urn:iungo:dxf/> SELECT * WHERE { GRAPH
>>>> <urn:iungo:dxf/graph/309ea4ce-dbdf-4d92-9828-1d99d35d0bb4> { {
>>>> ?equipment
>>>> dxf:attribute ?attribute  } . }}"
>>>>
>>>>
>>>> i.e. I remove the optional clause both queries return...
>>>>
>>>> dick@Dick-M3800:/media/dick/Backup1/bc$ wget -O q1 --header "accept:
>>>> text/plain" "http://localhost:8080/tdb/sparql?query=PREFIX dxf:
>>>> <urn:iungo:dxf/> SELECT * WHERE { GRAPH
>>>> <urn:iungo:dxf/graph/309ea4ce-dbdf-4d92-9828-1d99d35d0bb4> { {
>>>> ?equipment
>>>> dxf:attribute ?attribute  } . }}" & wget -O q2 --header "accept:
>>>> text/plain" "http://localhost:8080/tdb/sparql?query=PREFIX dxf:
>>>> <urn:iungo:dxf/> SELECT * WHERE { GRAPH
>>>> <urn:iungo:dxf/graph/309ea4ce-dbdf-4d92-9828-1d99d35d0bb4> { {
>>>> ?equipment
>>>> dxf:attribute ?attribute  } . }}"
>>>> [1] 7898
>>>> --2016-10-17 11:14:27--
>>>>
>>>> http://localhost:8080/tdb/sparql?query=PREFIX%20dxf:%20%3Cur
>> n:iungo:dxf/%3E%20SELECT%20*%20WHERE%20%7B%20GRAPH%20%3Curn
>> :iungo:dxf/graph/309ea4ce-dbdf-4d92-9828-1d99d35d0bb4%
>> 3E%20%7B%20%7B%20?equipment%20dxf:attribute%20?attribute%
>> 20%20%7D%20.%20%7D%7D
>>
>>> Resolving localhost (localhost)... --2016-10-17 11:14:27--
>>>>
>>>> http://localhost:8080/tdb/sparql?query=PREFIX%20dxf:%20%3Cur
>> n:iungo:dxf/%3E%20SELECT%20*%20WHERE%20%7B%20GRAPH%20%3Curn
>> :iungo:dxf/graph/309ea4ce-dbdf-4d92-9828-1d99d35d0bb4%
>> 3E%20%7B%20%7B%20?equipment%20dxf:attribute%20?attribute%
>> 20%20%7D%20.%20%7D%7D
>>
>>> Resolving localhost (localhost)... 127.0.0.1
>>>> Connecting to localhost (localhost)|127.0.0.1|:8080... connected.
>>>> HTTP request sent, awaiting response... 127.0.0.1
>>>> Connecting to localhost (localhost)|127.0.0.1|:8080... connected.
>>>> HTTP request sent, awaiting response... 200 OK
>>>> 200 OK
>>>> Length: Length: unspecifiedunspecified [text/plain]
>>>>  [text/plain]
>>>> Saving to: ‘q2’
>>>> Saving to: ‘q1’
>>>>
>>>>
>>>> q2                                          [<=>
>>>>                                                   ]       0  --.-KB/s
>>>>         qq1                                          [ <=>
>>>>                                                            ] 438.81K
>>>>  --.-KB/s    in 0.05s
>>>>
>>>> 2016-10-17 11:14:28 (8.19 MB/s) - ‘q1’ saved [449344]
>>>>
>>>> q2                                          [ <=>
>>>>                                                  ] 438.81K  --.-KB/s
>>>>
>>> in
>>
>>> 0.05s
>>>>
>>>> 2016-10-17 11:14:28 (8.09 MB/s) - ‘q2’ saved [449344]
>>>>
>>>> [1]+  Done                    wget -O q1 --header "accept: text/plain" "
>>>> http://localhost:8080/tdb/sparql?query=PREFIX dxf: <urn:iungo:dxf/>
>>>>
>>> SELECT
>>
>>> * WHERE { GRAPH
>>>>
>>> <urn:iungo:dxf/graph/309ea4ce-dbdf-4d92-9828-1d99d35d0bb4>
>>
>>> { { ?equipment dxf:attribute ?attribute  } . }}"
>>>> dick@Dick-M3800:/media/dick/Backup1/bc$
>>>>
>>>>
>>

Reply via email to