You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@cocoon.apache.org by Antonio Fiol Bonnín <an...@gmail.com> on 2005/11/03 13:28:04 UTC

Strange caching issue: need to reload twice

Hello,

With current SVN version, and also with 2.1.7, I am seeing a strange
caching issue: For a certain document (relevant sitemap portions
attached below), when the source (a directory) changes, I need to
reload twice to get the right content in my browser.

Any help tracking this problem would be greatly appreciated.

Yours sincerely,


Antonio Fiol




Times removed from logs to improve clarity. Logs from current SVN version.

*** First reload after creating a new file in the directory spits the
following into cocoon.log:

[core.manager] (/previsualizar/interno/inclusion/actualidad/resumen-noticias/listafechados-descendiente)
http-8080-Processor25/CacheImpl: Removing cached response for
PK_G-directory-file:/home/fiol/ficheros-intranet/compartido/paginas/actualidad/resumen-noticias/:1:null:name:true:1000:null:[0-9][0-9][0-9][0-9][-_][0-9][0-9][-_][0-9][0-9].*\.html:null:
[access] (/previsualizar/interno/inclusion/actualidad/resumen-noticias/listafechados-descendiente)
http-8080-Processor25/CocoonServlet:
'previsualizar/interno/inclusion/actualidad/resumen-noticias/listafechados-descendiente'
Processed by Apache Cocoon 2.1.8-rc1 in 59 milliseconds.



*** Second reload after changing the file gives:

[core.manager] (/previsualizar/interno/inclusion/actualidad/resumen-noticias/listafechados-descendiente)
http-8080-Processor25/CacheImpl: Removing cached response for
PK_G-file-cocoon://previsualizar/interno/datos/fechados/paginas/actualidad/resumen-noticias?pipelinehash=-2442472616783549200_T-xslt-file:/home/fiol/IdeaProjects/intranet/portal/dist/exploded/././xsl/xdoc/directory-fechados.xsl;path=actualidad/resumen-noticias_T-xslt-file:/home/fiol/IdeaProjects/intranet/portal/dist/exploded/././xsl/tmp/xinclude-previsualizacion.xsl_S-xml-1
[core.manager] (/previsualizar/interno/inclusion/actualidad/resumen-noticias/listafechados-descendiente)
http-8080-Processor25/CacheImpl: Caching new response for
PK_G-directory-file:/home/fiol/ficheros-intranet/compartido/paginas/actualidad/resumen-noticias/:1:null:name:true:1000:null:[0-9][0-9][0-9][0-9][-_][0-9][0-9][-_][0-9][0-9].*\.html:null:
[core.manager] (/previsualizar/interno/inclusion/actualidad/resumen-noticias/listafechados-descendiente)
http-8080-Processor25/CacheImpl: Caching new response for
PK_G-file-cocoon://previsualizar/interno/datos/fechados/paginas/actualidad/resumen-noticias?pipelinehash=-2442472616783549200_T-xslt-file:/home/fiol/IdeaProjects/intranet/portal/dist/exploded/././xsl/xdoc/directory-fechados.xsl;path=actualidad/resumen-noticias_T-xslt-file:/home/fiol/IdeaProjects/intranet/portal/dist/exploded/././xsl/tmp/xinclude-previsualizacion.xsl_S-xml-1
[access] (/previsualizar/interno/inclusion/actualidad/resumen-noticias/listafechados-descendiente)
http-8080-Processor25/CocoonServlet:
'previsualizar/interno/inclusion/actualidad/resumen-noticias/listafechados-descendiente'
Processed by Apache Cocoon 2.1.8-rc1 in 726 milliseconds.


*** Relevant sitemap portions:
<map:match pattern="datos/fechados/paginas/**">
   <map:generate type="directory" src="{naming:java:comp/env/paginas}/{1}">
       <map:parameter name="include"
value="[0-9][0-9][0-9][0-9][-_][0-9][0-9][-_][0-9][0-9].*\.html" />
       <map:parameter name="reverse" value="true" />
       <map:parameter name="sort" value="name" />
       <map:parameter name="depth" value="1" />
   </map:generate>
   <map:serialize />
</map:match>

<map:match pattern="inclusion/**/listafechados-descendiente">
    <map:generate src="cocoon:/datos/fechados/paginas/{1}" />
    <map:transform src="xsl/xdoc/directory-fechados.xsl">
         <map:parameter name="path" value="{1}" />
    </map:transform>
    <map:transform src='xsl/tmp/xinclude-previsualizacion.xsl' />
    <map:serialize/>
</map:match>




--
Antonio

---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@cocoon.apache.org
For additional commands, e-mail: users-help@cocoon.apache.org


Re: Strange caching issue: need to reload twice

Posted by Antonio Fiol Bonnín <an...@gmail.com>.
2005/11/3, Antonio Fiol Bonnín <an...@gmail.com>:
> Hello,
>
> With current SVN version, and also with 2.1.7, I am seeing a strange
> caching issue: For a certain document (relevant sitemap portions
> attached below), when the source (a directory) changes, I need to
> reload twice to get the right content in my browser.
>
> Any help tracking this problem would be greatly appreciated.
>
> Yours sincerely,
>
>
> Antonio Fiol
>
>
>
>
> Times removed from logs to improve clarity. Logs from current SVN version.
>
> *** First reload after creating a new file in the directory spits the
> following into cocoon.log:
>
> [core.manager] (/previsualizar/interno/inclusion/actualidad/resumen-noticias/listafechados-descendiente)
> http-8080-Processor25/CacheImpl: Removing cached response for
> PK_G-directory-file:/home/fiol/ficheros-intranet/compartido/paginas/actualidad/resumen-noticias/:1:null:name:true:1000:null:[0-9][0-9][0-9][0-9][-_][0-9][0-9][-_][0-9][0-9].*\.html:null:
> [access] (/previsualizar/interno/inclusion/actualidad/resumen-noticias/listafechados-descendiente)
> http-8080-Processor25/CocoonServlet:
> 'previsualizar/interno/inclusion/actualidad/resumen-noticias/listafechados-descendiente'
> Processed by Apache Cocoon 2.1.8-rc1 in 59 milliseconds.
>
>
>
> *** Second reload after changing the file gives:
>
> [core.manager] (/previsualizar/interno/inclusion/actualidad/resumen-noticias/listafechados-descendiente)
> http-8080-Processor25/CacheImpl: Removing cached response for
> PK_G-file-cocoon://previsualizar/interno/datos/fechados/paginas/actualidad/resumen-noticias?pipelinehash=-2442472616783549200_T-xslt-file:/home/fiol/IdeaProjects/intranet/portal/dist/exploded/././xsl/xdoc/directory-fechados.xsl;path=actualidad/resumen-noticias_T-xslt-file:/home/fiol/IdeaProjects/intranet/portal/dist/exploded/././xsl/tmp/xinclude-previsualizacion.xsl_S-xml-1
> [core.manager] (/previsualizar/interno/inclusion/actualidad/resumen-noticias/listafechados-descendiente)
> http-8080-Processor25/CacheImpl: Caching new response for
> PK_G-directory-file:/home/fiol/ficheros-intranet/compartido/paginas/actualidad/resumen-noticias/:1:null:name:true:1000:null:[0-9][0-9][0-9][0-9][-_][0-9][0-9][-_][0-9][0-9].*\.html:null:
> [core.manager] (/previsualizar/interno/inclusion/actualidad/resumen-noticias/listafechados-descendiente)
> http-8080-Processor25/CacheImpl: Caching new response for
> PK_G-file-cocoon://previsualizar/interno/datos/fechados/paginas/actualidad/resumen-noticias?pipelinehash=-2442472616783549200_T-xslt-file:/home/fiol/IdeaProjects/intranet/portal/dist/exploded/././xsl/xdoc/directory-fechados.xsl;path=actualidad/resumen-noticias_T-xslt-file:/home/fiol/IdeaProjects/intranet/portal/dist/exploded/././xsl/tmp/xinclude-previsualizacion.xsl_S-xml-1
> [access] (/previsualizar/interno/inclusion/actualidad/resumen-noticias/listafechados-descendiente)
> http-8080-Processor25/CocoonServlet:
> 'previsualizar/interno/inclusion/actualidad/resumen-noticias/listafechados-descendiente'
> Processed by Apache Cocoon 2.1.8-rc1 in 726 milliseconds.
>
>
> *** Relevant sitemap portions:
> <map:match pattern="datos/fechados/paginas/**">
>    <map:generate type="directory" src="{naming:java:comp/env/paginas}/{1}">
>        <map:parameter name="include"
> value="[0-9][0-9][0-9][0-9][-_][0-9][0-9][-_][0-9][0-9].*\.html" />
>        <map:parameter name="reverse" value="true" />
>        <map:parameter name="sort" value="name" />
>        <map:parameter name="depth" value="1" />
>    </map:generate>
>    <map:serialize />
> </map:match>
>
> <map:match pattern="inclusion/**/listafechados-descendiente">
>     <map:generate src="cocoon:/datos/fechados/paginas/{1}" />
>     <map:transform src="xsl/xdoc/directory-fechados.xsl">
>          <map:parameter name="path" value="{1}" />
>     </map:transform>
>     <map:transform src='xsl/tmp/xinclude-previsualizacion.xsl' />
>     <map:serialize/>
> </map:match>
>


Previous logs were generated using:
<map:pipe name="caching"
src="org.apache.cocoon.components.pipeline.impl.CachingProcessingPipeline">
</map:pipe>


These use:
<map:pipe name="caching"
src="org.apache.cocoon.components.pipeline.impl.CachingPointProcessingPipeline">
   <parameter name="autoCachingPoint" value="On"/>
</map:pipe>


Symptoms are identical.

*** First reload:
[core.manager] (/previsualizar/interno/inclusion/actualidad/resumen-noticias/listafechados-descendiente)
http-8080-Processor24/CacheImpl: Removing cached response for
PK_G-directory-file:/home/fiol/ficheros-intranet/compartido/paginas/actualidad/resumen-noticias/:1:null:name:true:1000:null:[0-9][0-9][0-9][0-9][-_][0-9][0-9][-_][0-9][0-9].*\.html:null:
[access] (/previsualizar/interno/inclusion/actualidad/resumen-noticias/listafechados-descendiente)
http-8080-Processor24/CocoonServlet:
'previsualizar/interno/inclusion/actualidad/resumen-noticias/listafechados-descendiente'
Processed by Apache Cocoon 2.1.8-rc1 in 176 milliseconds.


*** Second reload:
[core.manager] (/previsualizar/interno/inclusion/actualidad/resumen-noticias/listafechados-descendiente)
http-8080-Processor23/CacheImpl: Removing cached response for
PK_G-file-cocoon://previsualizar/interno/datos/fechados/paginas/actualidad/resumen-noticias?pipelinehash=-2442472616783549200_T-xslt-file:/home/fiol/IdeaProjects/intranet/portal/dist/exploded/././xsl/xdoc/directory-fechados.xsl;path=actualidad/resumen-noticias_T-xslt-file:/home/fiol/IdeaProjects/intranet/portal/dist/exploded/././xsl/tmp/xinclude-previsualizacion.xsl_S-xml-1
[core.manager] (/previsualizar/interno/inclusion/actualidad/resumen-noticias/listafechados-descendiente)
http-8080-Processor23/CacheImpl: Caching new response for
PK_G-directory-file:/home/fiol/ficheros-intranet/compartido/paginas/actualidad/resumen-noticias/:1:null:name:true:1000:null:[0-9][0-9][0-9][0-9][-_][0-9][0-9][-_][0-9][0-9].*\.html:null:
[core.manager] (/previsualizar/interno/inclusion/actualidad/resumen-noticias/listafechados-descendiente)
http-8080-Processor23/CacheImpl: Caching new response for
PK_G-file-cocoon://previsualizar/interno/datos/fechados/paginas/actualidad/resumen-noticias?pipelinehash=-2442472616783549200_T-xslt-file:/home/fiol/IdeaProjects/intranet/portal/dist/exploded/././xsl/xdoc/directory-fechados.xsl;path=actualidad/resumen-noticias_T-xslt-file:/home/fiol/IdeaProjects/intranet/portal/dist/exploded/././xsl/tmp/xinclude-previsualizacion.xsl_S-xml-1
[core.manager] (/previsualizar/interno/inclusion/actualidad/resumen-noticias/listafechados-descendiente)
http-8080-Processor23/CacheImpl: Caching new response for
PK_G-file-cocoon://previsualizar/interno/datos/fechados/paginas/actualidad/resumen-noticias?pipelinehash=-2442472616783549200_T-xslt-file:/home/fiol/IdeaProjects/intranet/portal/dist/exploded/././xsl/xdoc/directory-fechados.xsl;path=actualidad/resumen-noticias_T-xslt-file:/home/fiol/IdeaProjects/intranet/portal/dist/exploded/././xsl/tmp/xinclude-previsualizacion.xsl
[core.manager] (/previsualizar/interno/inclusion/actualidad/resumen-noticias/listafechados-descendiente)
http-8080-Processor23/ExcaliburComponentManager: Attempted to release
a org.apache.cocoon.components.sax.XMLByteStreamCompiler but its
handler could not be located.
[access] (/previsualizar/interno/inclusion/actualidad/resumen-noticias/listafechados-descendiente)
http-8080-Processor23/CocoonServlet:
'previsualizar/interno/inclusion/actualidad/resumen-noticias/listafechados-descendiente'
Processed by Apache Cocoon 2.1.8-rc1 in 727 milliseconds.


Any help, pointer, or advice will be greatly appreciated.

--
Antonio

---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@cocoon.apache.org
For additional commands, e-mail: users-help@cocoon.apache.org


Re: Strange caching issue: need to reload twice

Posted by Antonio Fiol Bonnín <an...@gmail.com>.
> 2005/11/3, Sylvain Wallez <sy...@apache.org>:
> > Hmm... could this be related to the refresh delay of the directory
> > generator[1]?
> >
> > What happens if you add <map:parameter name="refreshDelay" value="0"/>
> > in the <generate type="directory"> ?
>
> Sylvain, we tested value="0", and got the same effect.
>
> Going slightly further, we tried with value="-1", and amazingly
> enough, it worked.
>
> AFAICS, this must be a bug somewhere, as Cocoon is not refreshing at
> the first attempt even after an amount of time far longer than one
> second (except with value="-1"). We have little knowledge on Cocoon
> internals, but we were looking into the DirectoryGenerator (and
> DirValidity) and found nothing strange.


Hello,

I finally found something strange in DirectoryGenerator that could
explain the bug. In DirValidity we added some traces:

        public int isValid() {
            if (System.currentTimeMillis() <= expiry) {
                logger.debug(this + ": isValid() ==> 1 (not expired)");
                return 1;
            }

            expiry = System.currentTimeMillis() + delay; /* *****
SHOULD THIS LINE BE REMOVED? !!! ***** */
            int len = files.size();
            for (int i = 0; i < len; i++) {
                File f = (File)files.get(i);
                if (!f.exists()) {
                    logger.debug(this + ": isValid() ==> -1 (file
"+f+" removed)");
                    return -1; // File was removed
                }

                long oldDate = ((Long)fileDates.get(i)).longValue();
                long newDate = f.lastModified();

                if (oldDate != newDate) {
                    logger.debug(this + ": isValid() ==> -1 (different
dates for "+f+": "+oldDate+"!="+newDate+")");
                    return -1;
                }
            }

            // all content is up to date: update the expiry date
            expiry = System.currentTimeMillis() + delay;
            logger.debug(this + ": isValid() ==> 1 (all valid)");
            return 1;
        }


I think the tagged line should be removed. I can't see why it is
there, and I think it is responsible for the harm. When reloading
after changing a file, we get:

[sitemap.generator.directory]
org.apache.cocoon.generation.DirectoryGenerator$DirValidity@f4d063
Expiry: 1131363743861 - Delay: 1000: isValid() ==> -1 (different dates
for /home/fiol/ficheros-intranet/compartido/paginas/actualidad/resumen-noticias:
1131037742000!=1131363738000)
[sitemap.generator.directory]
org.apache.cocoon.generation.DirectoryGenerator$DirValidity@f4d063
Expiry: 1131363743861 - Delay: 1000: isValid() ==> 1 (not expired)

So apparently isValid is called twice, with inconsistent results
(first is OK, second is wrong, unless *I* am wrong ;-).

Aside from that, is the recycle method called before calling
generate() if cache is invalid? Supposing it is not, how is the
DirValidity refreshed with new files? More specifically, how are old
ones removed? There is no point in the code where this.validity is
made null other than the recycle method.

As I told you, I know very little about Cocoon internals, but there
seems to be something broken here.

--
Antonio

---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@cocoon.apache.org
For additional commands, e-mail: users-help@cocoon.apache.org


Re: Strange caching issue: need to reload twice

Posted by Antonio Fiol Bonnín <an...@gmail.com>.
> 2005/11/3, Sylvain Wallez <sy...@apache.org>:
> > Hmm... could this be related to the refresh delay of the directory
> > generator[1]?
> >
> > What happens if you add <map:parameter name="refreshDelay" value="0"/>
> > in the <generate type="directory"> ?
>
> Sylvain, we tested value="0", and got the same effect.
>
> Going slightly further, we tried with value="-1", and amazingly
> enough, it worked.
>
> AFAICS, this must be a bug somewhere, as Cocoon is not refreshing at
> the first attempt even after an amount of time far longer than one
> second (except with value="-1"). We have little knowledge on Cocoon
> internals, but we were looking into the DirectoryGenerator (and
> DirValidity) and found nothing strange.


Hello,

I finally found something strange in DirectoryGenerator that could
explain the bug. In DirValidity we added some traces:

        public int isValid() {
            if (System.currentTimeMillis() <= expiry) {
                logger.debug(this + ": isValid() ==> 1 (not expired)");
                return 1;
            }

            expiry = System.currentTimeMillis() + delay; /* *****
SHOULD THIS LINE BE REMOVED? !!! ***** */
            int len = files.size();
            for (int i = 0; i < len; i++) {
                File f = (File)files.get(i);
                if (!f.exists()) {
                    logger.debug(this + ": isValid() ==> -1 (file
"+f+" removed)");
                    return -1; // File was removed
                }

                long oldDate = ((Long)fileDates.get(i)).longValue();
                long newDate = f.lastModified();

                if (oldDate != newDate) {
                    logger.debug(this + ": isValid() ==> -1 (different
dates for "+f+": "+oldDate+"!="+newDate+")");
                    return -1;
                }
            }

            // all content is up to date: update the expiry date
            expiry = System.currentTimeMillis() + delay;
            logger.debug(this + ": isValid() ==> 1 (all valid)");
            return 1;
        }


I think the tagged line should be removed. I can't see why it is
there, and I think it is responsible for the harm. When reloading
after changing a file, we get:

[sitemap.generator.directory]
org.apache.cocoon.generation.DirectoryGenerator$DirValidity@f4d063
Expiry: 1131363743861 - Delay: 1000: isValid() ==> -1 (different dates
for /home/fiol/ficheros-intranet/compartido/paginas/actualidad/resumen-noticias:
1131037742000!=1131363738000)
[sitemap.generator.directory]
org.apache.cocoon.generation.DirectoryGenerator$DirValidity@f4d063
Expiry: 1131363743861 - Delay: 1000: isValid() ==> 1 (not expired)

So apparently isValid is called twice, with inconsistent results
(first is OK, second is wrong, unless *I* am wrong ;-).

Aside from that, is the recycle method called before calling
generate() if cache is invalid? Supposing it is not, how is the
DirValidity refreshed with new files? More specifically, how are old
ones removed? There is no point in the code where this.validity is
made null other than the recycle method.

As I told you, I know very little about Cocoon internals, but there
seems to be something broken here.

--
Antonio

Re: Strange caching issue: need to reload twice

Posted by Antonio Fiol Bonnín <an...@gmail.com>.
Sylvain, Joerg,

Thank you both for your responses.

2005/11/3, Sylvain Wallez <sy...@apache.org>:
> Hmm... could this be related to the refresh delay of the directory
> generator[1]?
>
> What happens if you add <map:parameter name="refreshDelay" value="0"/>
> in the <generate type="directory"> ?

Sylvain, we tested value="0", and got the same effect.

Going slightly further, we tried with value="-1", and amazingly
enough, it worked.

AFAICS, this must be a bug somewhere, as Cocoon is not refreshing at
the first attempt even after an amount of time far longer than one
second (except with value="-1"). We have little knowledge on Cocoon
internals, but we were looking into the DirectoryGenerator (and
DirValidity) and found nothing strange.

Joerg, I do not know of any mechanism of background reloading. In
fact, I doubt it, as the logs show that the caching of the new
response happens on the second reload.

The problem seems somewhere else, but have no idea where to look. Any
hints would be appreciated.

--
Antonio

---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@cocoon.apache.org
For additional commands, e-mail: users-help@cocoon.apache.org


Re: Strange caching issue: need to reload twice

Posted by Joerg Heinicke <jo...@gmx.de>.
On 03.11.2005 20:42, Antonio Fiol Bonnín wrote:

>>Hmm... could this be related to the refresh delay of the directory
>>generator[1]?

I also don't think that it is an issue of the delay. This would prevent 
checking the validness completely IIRC.

> - The logs show that the cached response *is* removed on the first
> reload attempt, but is *not* cached again (generated again?) until the
> second reload.  I cannot guess why a content which is removed from the
> cache is not generated and re-cached immediately after that.

It sounds more like a behaviour where the cache is checked, not taken 
for valid, but the old content is delivered once again while the new 
content is generated in background. Does Cocoon have such a caching 
strategy anywhere?

Jörg

---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@cocoon.apache.org
For additional commands, e-mail: users-help@cocoon.apache.org


Re: Strange caching issue: need to reload twice

Posted by Antonio Fiol Bonnín <an...@gmail.com>.
2005/11/3, Sylvain Wallez <sy...@apache.org>:
> Antonio Fiol Bonnín wrote:
> > Hello,
> >
> > With current SVN version, and also with 2.1.7, I am seeing a strange
> > caching issue: For a certain document (relevant sitemap portions
> > attached below), when the source (a directory) changes, I need to
> > reload twice to get the right content in my browser.
> >
> > Any help tracking this problem would be greatly appreciated.
> >
>
> Hmm... could this be related to the refresh delay of the directory
> generator[1]?


Dear Sylvain,

First of all, thank you for pointing this out: I had completely
disregarded this possibility, not thinking this could be a time issue
but a validity issue..


> What happens if you add <map:parameter name="refreshDelay" value="0"/>
> in the <generate type="directory"> ?


We will try it tomorrow morning, as soon as I get to the office.

However, at first glance, I do not think this might solve the issue because:

- The effect does not seem to depend on time. It takes us a fair
amount of time (far more than 1 second - the default delay - in any
case) to create/delete a file in the directory and hit the first
reload.

- The logs show that the cached response *is* removed on the first
reload attempt, but is *not* cached again (generated again?) until the
second reload.  I cannot guess why a content which is removed from the
cache is not generated and re-cached immediately after that.

WDYT?

--
Antonio

---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@cocoon.apache.org
For additional commands, e-mail: users-help@cocoon.apache.org


Re: Strange caching issue: need to reload twice

Posted by Sylvain Wallez <sy...@apache.org>.
Antonio Fiol Bonnín wrote:
> Hello,
>
> With current SVN version, and also with 2.1.7, I am seeing a strange
> caching issue: For a certain document (relevant sitemap portions
> attached below), when the source (a directory) changes, I need to
> reload twice to get the right content in my browser.
>
> Any help tracking this problem would be greatly appreciated.
>   

Hmm... could this be related to the refresh delay of the directory 
generator[1]?

What happens if you add <map:parameter name="refreshDelay" value="0"/> 
in the <generate type="directory"> ?

Sylvain


[1] 
http://cocoon.apache.org/2.1/userdocs/generators/directory-generator.html

-- 
Sylvain Wallez                        Anyware Technologies
http://people.apache.org/~sylvain     http://www.anyware-tech.com
Apache Software Foundation Member     Research & Technology Director


---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@cocoon.apache.org
For additional commands, e-mail: users-help@cocoon.apache.org