Re: [Exist-development] Strange PathExpr warnings in log....

[Wolfgang M. <wol...@ex...>]

Andrzej,

the warnings are coming from the XQuery optimizer and can be safely
ignored. They point to an optimizer issue though: I recently tried to
make the compiled XQuery expression tree more lightweight and removed
a few intermediate objects. Obviously I did too much and broke some
optimizations.

I still need to look into this.

Wolfgang


2011/5/18 Andrzej Jan Taramina <an...@ch...>:
> Wolfgang:
>
> I'm testing latest trunk.  Getting a bunch of warnings like the following:
>
> 2011-05-18 12:30:28,671 [DefaultQuartzScheduler_Worker-4] WARN  (PathExpr.java
> [replaceExpression]:119) - Expression not found: $matchDate[child::v3:code/attribute::codeSystem =
> $syscode]; in: exists($syscode)
> 2011-05-18 12:30:28,671 [DefaultQuartzScheduler_Worker-4] WARN  (PathExpr.java
> [replaceExpression]:119) - Expression not found: $matchDate[child::v3:code/attribute::codeSystemName
> = $sysname]; in: exists($sysname)
> 2011-05-18 12:30:28,671 [DefaultQuartzScheduler_Worker-4] WARN  (PathExpr.java
> [replaceExpression]:119) - Expression not found:
> $matchValCode[text:matches-regex(child::v3:statusCode/attribute::code, $pattern)]; in:
> $caseSensitive = "true"
> 2011-05-18 12:30:28,673 [DefaultQuartzScheduler_Worker-4] WARN  (PathExpr.java
> [replaceExpression]:119) - Expression not found: $encounters[contains(child::v3:text, $pattern)];
> in: $caseSensitive = "true"
> 2011-05-18 12:30:28,673 [DefaultQuartzScheduler_Worker-4] WARN  (PathExpr.java
> [replaceExpression]:119) - Expression not found: $observations[contains(child::v3:value, $pattern)];
> in: $caseSensitive = "true"
> 2011-05-18 12:30:28,673 [DefaultQuartzScheduler_Worker-4] WARN  (PathExpr.java
> [replaceExpression]:119) - Expression not found: $observations[text:matches-regex(child::v3:value,
> $pattern)]; in: $caseSensitive = "true"
> 2011-05-18 12:30:28,674 [DefaultQuartzScheduler_Worker-4] WARN  (PathExpr.java
> [replaceExpression]:119) - Expression not found:
> $observations[contains(child::v3:value/attribute::value, $pattern)]; in: $caseSensitive = "true"
> 2011-05-18 12:30:28,674 [DefaultQuartzScheduler_Worker-4] WARN  (PathExpr.java
> [replaceExpression]:119) - Expression not found:
> $observations[text:matches-regex(child::v3:value/attribute::value, $pattern)]; in: $caseSensitive =
> "true"
> 2011-05-18 12:30:28,675 [DefaultQuartzScheduler_Worker-4] WARN  (PathExpr.java
> [replaceExpression]:119) - Expression not found:
> common:get-sections-with-data($patientRecord)[common:get-section-id(self::node()) = $id]; in:
> common:get-section-by-id(item()*, item()*) item()*
>
> Which just look very suspicious, since I don't see how the new and old expressions might be
> related....and I've never seen these warnings in the past.
>
> I wonder if it might be related to the repeated attribute expression values bug that I've been
> seeing (copied that post below for reference) since both relate to expression handling in XQuery?
>
> I still haven't managed to create a simple test case (I've been trying!) to replicate the repeated
> attribute bug....though in my production XQuery code (which is very complex) it happens consistently.
>
> Help!
>
> Thanks.
>
> .....Andrzej
>
>> More testing on this issue:
>>
>> I changed the test function to not use the Binary stuff, so it looks like this:
>>
>> declare function common:test()
>> {
>>     let $line := <property name="java.naming.security.credentials"
>>                          value="{ xs:string( 'dGVzdA==' ) }"/>
>>
>>     let $debug2 := util:log-system-out( concat( "Credentials XML String: ",
>>                      util:serialize(  $line, "method=xml media-type=text/xml indent=yes" ) ) )
>>
>>     return $line
>> };
>>
>> And I still get the erroneous result, with 8 repeated values:
>>
>> (Line: 494) Credentials XML String: <property name="java.naming.security.credentials"
>>             value="dGVzdA== dGVzdA== dGVzdA== dGVzdA== dGVzdA== dGVzdA== dGVzdA== dGVzdA=="/>
>>
>>
>> So that means your Binary stuff is off the hook, Adam!  The problem is somewhere else....maybe in
>> the query parser or execution engine.
>>
>> Changing the line that creates the xml snippet to:
>>
>>    let $line := <property name="java.naming.security.credentials"
>>                         value="{ let $tmp := 'dGVzdA==' return $tmp }"/>
>>
>> shows the same issue....8 repeated strings, delimited with a space for the @value attribute.
>>
>> But this variant does NOT repeat the values!
>>
>>       let $tmp := 'dGVzdA=='
>>
>>       let $line := <property name="java.naming.security.credentials" value="{ $tmp }"/>
>>
>> and neither does this one:
>>
>>       let $tmp := 'dGVzdA=='
>>
>>       let $line := <property name="java.naming.security.credentials"
>>                              value="{ xs:string( 'dGVzdA==' ) }"/>
>>
>> Which leads me to believe that the bug is partially position sensitive.  If the creation of the xml
>> snippet is the first line of code in the function, then the values get replicated 8 times.  If there
>> is any code prior to that line, then it does not replicate.
>>
>> I then changed the test function to take a parameter (the string being replicated) and changed the
>> calling function to pass in the string:
>>
>> So this version:
>>
>> declare function common:test( $tmp )
>> {
>>     let $line := <property name="java.naming.security.credentials" value="{ xs:string( $tmp ) }"/>
>>
>>     .....
>> };
>>
>> replicates the attribute value 8 times (showing the bug), but this one:
>>
>> declare function common:test( $tmp )
>> {
>>     let $line := <property name="java.naming.security.credentials" value="{ $tmp }"/>
>>
>>     .....
>> };
>>
>> does not replicate (no bug!).
>>
>> This leads me to believe that the bug is somewhere in how code fragments inside attribute values are
>> evaluated.
>>
>> Not being very familiar with the xquery parser nor evaluation engine, I can't easily dive into the
>> code (which is very complex) to figure out what is going on. I'm hoping that all of these different
>> test cases might twig something with you, Wolfgang, since creating a simple test case to replicate
>> this is proving difficult.
>>
>> .....Andrzej
>>
>>
>>> > On 30 April 2011 00:55, Andrzej Jan Taramina <an...@ch...> wrote:
>>>> >> Wolfgang:
>>>> >>
>>>> >> I've hit a very weird error in trunk, that could potentially be very serious.
>>>> >>
>>>> >> I have some code in a module that looks like this:
>>>> >>
>>>> >> declare function common:test()
>>>> >> {
>>>> >>    let $line := <property name="java.naming.security.credentials"
>>>> >>                           value="{ util:binary-to-string( xs:base64Binary( 'dGVzdAoK' ) ) }"/>
>>>> >>
>>>> >>    let $debug2 := util:log-system-out( concat( "Credentials XML: ",
>>>> >>                        util:serialize(  $line, "method=xml media-type=text/xml indent=yes" ) ) )
>>>> >>
>>>> >>    return $line
>>>> >> };
>>>> >>
>>>> >> declare function common:get-ldap-connection()  as xs:integer
>>>> >> {
>>>> >>    let $test := common:test()
>>>> >>
>>>> >>    let $contextProps :=
>>>> >>    <properties>
>>>> >>       <property name="java.naming.factory.initial" value="com.sun.jndi.ldap.LdapCtxFactory"/>
>>>> >>       <property name="java.naming.provider.url"
>>>> >>                 value="{ common:get-config()/config/ldap/url/text() }"/>
>>>> >>       <property name="java.naming.security.authentication" value="simple"/>
>>>> >>       <property name="java.naming.security.principal"
>>>> >>                 value="{ common:get-config()/config/ldap/adminUser/text() }"/>
>>>> >>       <property name="java.naming.security.credentials"
>>>> >>                 value="{ util:binary-to-string( xs:base64Binary(
>>>> >>                                common:get-config()/config/ldap/adminPswd/text() ) ) }"/>
>>>> >>    </properties>
>>>> >>
>>>> >>    let $ctx := jndi:get-dir-context( $contextProps )
>>>> >>
>>>> >>    return $ctx
>>>> >> };
>>>> >>
>>>> >> I then have a xquery that includes this module, and does something like this:
>>>> >>
>>>> >>        let $cnx := common:get-ldap-connection()
>>>> >>
>>>> >> All works fine if I call this from the sandbox and in the console log I will see the following line
>>>> >> produced by the common:test() function:
>>>> >>
>>>> >> (Line: 494) Credentials XML: <property name="java.naming.security.credentials"
>>>> >>                                       value="test&#xA;&#xA;"/>
>>>> >>
>>>> >>
>>>> >> The problem I run into is that when I run this xquery from the scheduler (which is how it's intended
>>>> >> to run...it's a batch reporting job), cause then I get the following output in the console log:
>>>> >>
>>>> >> (Line: 494) Credentials XML: <property name="java.naming.security.credentials" value="test&#xA;&#xA;
>>>> >> test&#xA;&#xA; test&#xA;&#xA; test&#xA;&#xA; test&#xA;&#xA; test&#xA;&#xA; test&#xA;&#xA;
>>>> >> test&#xA;&#xA;"/>
>>>> >>
>>>> >> I get 8 concatenated decoded values in the value attribute!!!!
>>>> >>
>>>> >> This should never happen!!!!  Of course, in that situation, I fail to get an LDAP connection since
>>>> >> the password (the credentials) is a concatenation of 8 copies of the actual password, and so fails,
>>>> >> if I remove the call to the test function.  If I leave in the call to the test function, then the
>>>> >> correct (non-replicated) password is inserted into the credentials element of the $contextProps
>>>> >> variable. If I remove the test function call, then I get the same replication in $contextProps.
>>>> >>
>>>> >> What is weird is that the error only shows in the one place and is sensitive to order. If I put the
>>>> >> call to the test function after the construction of the $contextProps value, then $contextProps gets
>>>> >> the repeated value and the test function returns a correct, unrepeated value.
>>>> >>
>>>> >> I've been trying to create a simple test case to replicate this, but have not yet been successful.
>>>> >> It seems I need to run the big batch job, where the included module is 3600 lines long, and the
>>>> >> actual xquery is very long and complex as well.
>>>> >>
>>>> >> But the code snippet that causes this bug is static code in the common:test() function, and should
>>>> >> always return the correct result.
>>>> >>
>>>> >> I'm not sure what is causing this.  Could it be the new Binary Value caching/handling under weird
>>>> >> conditions that only happen when running under a scheduled task?  I've never managed to reproduce
>>>> >> this when calling xqueries directly (the ldap connection call is made all over the place in our web
>>>> >> app for authentication purposes).  Maybe util:binary-to-string() is at fault, but that seems
>>>> >> unlikely.  Maybe some of your path wrapper stuff?
>>>> >>
>>>> >> This exact same code runs just fine as a scheduled task in an older version of trunk (from late
>>>> >> summer last year), so it's definitely something new in trunk that has manifested since then.
>>>> >>
>>>> >> Any ideas on what might cause something this strange?  I has me very worried since this is pretty
>>>> >> basic stuff....and thus might cause other things like DB corruption, or incorrect values being
>>>> >> written or wrong logic paths being followed.
>>>> >>
>>>> >> I'll keep trying to create a simple test case that illustrates this, but I think it may not be
>>>> >> possible to do so.
>>>> >>
>
> --
> Andrzej Taramina
> Chaeron Corporation: Enterprise System Solutions
> http://www.chaeron.com
>