Understanding / Debugging "ERROR cocoon.handled - Failed to process pipeline"

[Feed My Lambs Esq.]

There seems to be numerous instances of this error in one form or another.

Most if not all of those inquiries deal with a problem being experienced in the interface around a problem with their SOLR index but I am not experiencing any known issues - SOLR or otherwise! This error is not appearing in the interface to me but it is all over my error log and I'd like to fix it or at least know why it is happening.

It seems to clearly be an issue with the sitemap and what it is expecting to build, but I haven't been able to decipher/interpret it.

From cocoon.log for today:

(line prior)

2016-02-12 10:47:38,075 INFO  org.apache.cocoon.caching.impl.CacheImpl  - Cache MISS for PK_G-file-cocoon://DRI/favicon.ico?pipelinehash=-2267529246176899734_T-IncludePageMeta--5280603869656992694_T-IncludePageMeta-7145676799531262490_T-IncludePageMeta-1889180249406810576_T-xslt-file:///E:/dspace/webapps/xmlui/themes/BSU/BSU.xsl_T-i18n-context://i18n/?en_US__S-xhtml-;doctype-public=-//W3C//DTD XHTML 1.0 Strict//EN;doctype-system=http://www.w3.org/TR/xhtml1/DTD/xhtml1-strict.dtd;encoding=UTF-8;indent=yes

2016-02-12 10:47:38,090 ERROR cocoon.handled  - Failed to process pipeline

at <map:serialize type="xml"> - file:///E:/dspace/webapps/xmlui/aspects/aspects.xmap:96:31

at <map:generate type="file"> - file:///E:/dspace/webapps/xmlui/aspects/aspects.xmap:95:55

at <map:serialize type="xml"> - resource://aspects/ViewArtifacts/sitemap.xmap:359:32

at <map:transform type="Navigation"> - resource://aspects/ViewArtifacts/sitemap.xmap:91:59

at <map:generate> - resource://aspects/ViewArtifacts/sitemap.xmap:79:40

at <map:serialize type="xml"> - resource://aspects/BrowseArtifacts/sitemap.xmap:108:40

at <map:transform type="Navigation"> - resource://aspects/BrowseArtifacts/sitemap.xmap:47:47

at <map:generate> - resource://aspects/BrowseArtifacts/sitemap.xmap:41:28

at <map:serialize type="xml"> - resource://aspects/Discovery/sitemap.xmap:214:40

at <map:transform type="Navigation"> - resource://aspects/Discovery/sitemap.xmap:78:47

at <map:generate> - resource://aspects/Discovery/sitemap.xmap:66:28

at <map:serialize type="xml"> - resource://aspects/Administrative/sitemap.xmap:1074:31

at <map:transform type="Navigation"> - resource://aspects/Administrative/sitemap.xmap:299:38

at <map:transform type="SystemwideAlerts"> - resource://aspects/Administrative/sitemap.xmap:298:44

at <map:generate> - resource://aspects/Administrative/sitemap.xmap:296:19

at <map:serialize type="xml"> - resource://aspects/EPerson/sitemap.xmap:302:31

at <map:transform type="Navigation"> - resource://aspects/EPerson/sitemap.xmap:107:38

at <map:generate> - resource://aspects/EPerson/sitemap.xmap:96:19

at <map:serialize> - resource://aspects/Submission/sitemap.xmap:277:27

at <map:generate> - resource://aspects/Submission/sitemap.xmap:257:26

at <map:serialize type="xml"> - resource://aspects/Statistics/sitemap.xmap:292:36

at <map:generate> - resource://aspects/Statistics/sitemap.xmap:37:19

at <map:serialize> - resource://aspects/Workflow/sitemap.xmap:161:27

at <map:generate> - resource://aspects/Workflow/sitemap.xmap:145:26

at <map:serialize type="xml"> - file:///E:/dspace/webapps/xmlui/aspects/aspects.xmap:85:34

at <map:transform type="PageNotFound"> - file:///E:/dspace/webapps/xmlui/aspects/aspects.xmap:84:43

at <map:generate> - file:///E:/dspace/webapps/xmlui/aspects/aspects.xmap:83:22

at <map:serialize type="xhtml"> - file:///E:/dspace/webapps/xmlui/themes/BSU/sitemap.xmap:182:46

at <map:transform type="i18n"> - file:///E:/dspace/webapps/xmlui/themes/BSU/sitemap.xmap:104:44

at <map:transform> - file:///E:/dspace/webapps/xmlui/themes/BSU/sitemap.xmap:100:59

at <map:transform type="IncludePageMeta"> - file:///E:/dspace/webapps/xmlui/themes/BSU/sitemap.xmap:84:51

at <map:transform type="IncludePageMeta"> - file:///E:/dspace/webapps/xmlui/themes/BSU/sitemap.xmap:80:51

at <map:transform type="IncludePageMeta"> - file:///E:/dspace/webapps/xmlui/themes/BSU/sitemap.xmap:70:51

at <map:generate type="file"> - file:///E:/dspace/webapps/xmlui/themes/BSU/sitemap.xmap:174:67

at <map:match> - file:///E:/dspace/webapps/xmlui/themes/BSU/sitemap.xmap:170:37

Here is the content via E:/dspace/webapps/xmlui/aspects/aspects.xmap:96:31

<map:pipeline internal-only="yes">

<map:match type="AspectMatcher">

<map:select type="parameter">

<map:parameter name="parameter-selector-test" value="{aspectID}"/>

<map:when test="0">

<map:generate/>

<map:transform type="PageNotFound"/>

<map:serialize type="xml"/>

</map:when>

<map:otherwise>

<map:mount uri-prefix="{prefix}" check-reload="" src="{aspect}"/>

</map:otherwise>

</map:select>

</map:match>

<map:generate type="file" src="protodocument.xml"/> (line 95)

<map:serialize type="xml"/> (line 96)

</map:pipeline>

What else is necessary to debug a "Failed to process pipeline" error when you don't even notice a problem when navigating the UI?

Many thanks!

[Feed My Lambs Esq.]

I'm working with DSpace v5.5, Java 1.8.0_74, Tomcat 8, on a Windows 2012 server.

[Pottinger, Hardy J.]

Hi, from the example error you posted, I can see you have a "page not found" error, and there is a mention of a protodocument.xml file... which doesn't sound like standard DSpace... so I thought I'd ask: what is it you're trying to do? One thing I've noticed is these kinds of errors get thrown when the parser fails to process an XML file, due the xml file being missing, mal-formed, or otherwise contains an error. This is common enough (I am quite prone to typos) that I made this Jira [1] and Pull Request [2]. It ought to work with 5.4 (that where I wrote it originally, for my own repository's fork of DSpace).

--Hardy

[1] https://jira.duraspace.org/projects/DS/issues/DS-3056
[2] https://github.com/DSpace/DSpace/pull/1291

---

From: dspac...@googlegroups.com [dspac...@googlegroups.com] on behalf of Feed My Lambs Esq. [victor....@gmail.com]
Sent: Friday, February 12, 2016 10:41 AM
To: DSpace Technical Support
Subject: [dspace-tech] Understanding / Debugging "ERROR cocoon.handled - Failed to process pipeline"

--
You received this message because you are subscribed to the Google Groups "DSpace Technical Support" group.
To unsubscribe from this group and stop receiving emails from it, send an email to dspace-tech...@googlegroups.com.
To post to this group, send email to dspac...@googlegroups.com.
Visit this group at https://groups.google.com/group/dspace-tech.
For more options, visit https://groups.google.com/d/optout.

[Feed My Lambs Esq.]

Thanks Hardy!

I'm not sure what I'm "trying to do". Great question, though. I validated the XML for my sitemap.xmap and it said it was o.k. but I may have to end up compiling your pom change in just in hopes of seeing something that is wrong. I'm assuming the intention is that it kills a 'maven update' if it finds something wrong?

Here's more about the BSU/sitemap.xmap. Working from the bottom of the error stack, the block of code that starts the processing is the "Primary (non-caching) Pipeline".

        <map:pipeline>

            <!-- Never allow the browser to cache dynamic content -->

            <map:parameter name="expires" value="now"/>

            <map:match pattern="**"> (Line 170)

                <!-- Step 1: Generate the DRI page -->

                <!-- This line actually initiates the Aspect chain. The Aspect chain will build

                     the DRI (XML) content based on which page the user is accessing. -->

                <map:generate type="file" src="cocoon://DRI/{1}"/> (Line 174)

                <!-- Step 2: Transform the DRI page into XHTML -->

                <!-- This line calls the resource named 'transform-to-xhtml' (included above). 

                     That resource is in charge of tranforming this DRI content into XHTML -->

                <map:call resource="transform-to-xhtml"/>

                <!-- Step 3: Serialize to the browser (sends final XHTML to user's browser) -->

                <map:serialize type="xhtml"/> (Line 182 - The last line mentioned in the themes/BSU/ stack)

            </map:match>

        </map:pipeline>

The next part of the stack is lines 70, 80, and 84:

            <map:transform type="IncludePageMeta"> (Line 70)

                <map:parameter name="stylesheet.screen#1" value="lib/css/reset.css"/>

                <map:parameter name="stylesheet.screen#2" value="lib/css/base.css"/>

                <map:parameter name="stylesheet.screen#3" value="lib/css/helper.css"/>

                <map:parameter name="stylesheet.screen#4" value="lib/css/jquery-ui-1.8.15.custom.css"/>

                <map:parameter name="stylesheet.screen#5" value="lib/css/style.css"/>

                <map:parameter name="stylesheet.screen#6" value="lib/css/authority-control.css"/>

                <map:parameter name="stylesheet.screen#7" value="lib/css/BSU.css"/>

                <map:parameter name="stylesheet.screen#8" value="lib/css/jquery.bxslider.css"/>

            </map:transform>

            <map:transform type="IncludePageMeta"> (Line 80)

                <map:parameter name="stylesheet.handheld" value="lib/css/handheld.css"/>

                <map:parameter name="stylesheet.print" value="lib/css/print.css"/>

            </map:transform>

            <map:transform type="IncludePageMeta"> (Line 84)

                <map:parameter name="stylesheet.all" value="lib/css/media.css"/>

                <map:parameter name="javascript" value="lib/js/jquery-ui-1.8.15.custom.min.js"/> (For some reason I'm seeing every other include but not this one - it is in the same folder as BSU.js)

<map:parameter name="javascript" value="lib/js/BSU.js"/>

                <map:parameter name="theme.path" value="{global:theme-path}"/>

                <map:parameter name="theme.name" value="{global:theme-path}"/> (***A possible typo?***)

                <map:parameter name="curRequestURI" value="{1}"/>

            </map:transform>

Line 100 is:

<map:transform src="{global:theme-path}.xsl"/>

            <!-- Localize the XHTML page (by replacing i18n tags) -->

            <map:act type="locale">

                <map:transform type="i18n"> (Line 104)

                    <map:parameter name="locale" value="{locale}"/>

                </map:transform>

            </map:act>

As far as protodocument.xml is concerned, I don't think I created that. I found it also here in github:

https://github.com/DSpace/DSpace/blob/77e8c9a77c4951c86f194458a9d3c5105ebce753/dspace-xmlui/src/main/webapp/aspects/aspects.xmap

Is that give any clues? My src/main/webapp/aspects/aspects.xmap is identical.

I also noticed that the error I posted about first is a lot longer and continues like this:

at <map:match> - file:///E:/dspace/webapps/xmlui/themes/BSU/sitemap.xmap:170:37 (already shown; hundreds of lines follow though)

org.apache.cocoon.ProcessingException: Failed to process pipeline

at <map:serialize type="xml"> - file:///E:/dspace/webapps/xmlui/aspects/aspects.xmap:96:31

at <map:generate type="file"> - file:///E:/dspace/webapps/xmlui/aspects/aspects.xmap:95:55

at <map:serialize type="xml"> - resource://aspects/ViewArtifacts/sitemap.xmap:359:32

at <map:transform type="Navigation"> - resource://aspects/ViewArtifacts/sitemap.xmap:91:59

at <map:generate> - resource://aspects/ViewArtifacts/sitemap.xmap:79:40

at <map:serialize type="xml"> - resource://aspects/BrowseArtifacts/sitemap.xmap:108:40

at <map:transform type="Navigation"> - resource://aspects/BrowseArtifacts/sitemap.xmap:47:47

at <map:generate> - resource://aspects/BrowseArtifacts/sitemap.xmap:41:28

at <map:serialize type="xml"> - resource://aspects/Discovery/sitemap.xmap:214:40

at <map:transform type="Navigation"> - resource://aspects/Discovery/sitemap.xmap:78:47

at <map:generate> - resource://aspects/Discovery/sitemap.xmap:66:28

at <map:serialize type="xml"> - resource://aspects/Administrative/sitemap.xmap:1074:31

...

Caused by: org.apache.cocoon.ResourceNotFoundException: Page cannot be found

at org.dspace.app.xmlui.aspect.general.PageNotFoundTransformer.addBody(PageNotFoundTransformer.java:170)

at org.dspace.app.xmlui.wing.AbstractWingTransformer.startElement(AbstractWingTransformer.java:223)

... 314 more

I'll post this now and see if the additional info has helped. I'm not sure why there would be a "page not found" error when I've never seen it navigating around. I should mention that this error log is from a server that is only accessible to a select few people while we prepare to make it production and nobody involved in testing has mentioned any "page not found" navigation errors.

Thanks!

[Feed My Lambs Esq.]

Is it possible that this incredibly verbose error output (as many as 1500 lines) is all due to a simple page not found error?

Could someone test this in their 5_x repository and confirm that a fake handle (or any url that doesn't exist in the system) generates this super-long error in your cocoon log? Note the time to make it easier to track it.

Also, if I am interpreting my error logs correctly, it looks like sometimes the 'page not found' gets triggered on a request for the favicon which is weird since it always seems present to me in the browser tab. Here's our newly launched site to see for yourself: https://cardinalscholar.bsu.edu/

In the page-structure.xsl I have the following to present that icon.

            <link rel="shortcut icon">

                <xsl:attribute name="href">

                    <xsl:value-of select="/dri:document/dri:meta/dri:pageMeta/dri:metadata[@element='contextPath'][not(@qualifier)]"/>

                    <xsl:text>/themes/</xsl:text>

                    <xsl:value-of select="/dri:document/dri:meta/dri:pageMeta/dri:metadata[@element='theme'][@qualifier='path']"/>

                    <xsl:text>/images/favicon.ico</xsl:text>

                </xsl:attribute>

            </link>

and then (somehow) right before one of the "Failed to process pipeline" notices I see the following:

2016-02-16 00:35:50,783 INFO  org.apache.cocoon.caching.impl.CacheImpl  - Cache HIT for PK_G-file-file:///E:/dspace/webapps/xmlui/aspects/protodocument.xml

2016-02-16 00:35:50,783 INFO  org.apache.cocoon.caching.impl.CacheImpl  - Cache MISS for PK_G-aspect-cocoon://DRI/9/favicon.ico?pipelinehash=477348137205522819_T-Navigation-6131973275261880188

2016-02-16 00:35:50,783 INFO  org.apache.cocoon.caching.impl.CacheImpl  - Cache MISS for PK_G-aspect-cocoon://DRI/8/favicon.ico?pipelinehash=-5023394907477727460_T-Navigation-3212562138654597485

2016-02-16 00:35:50,783 INFO  org.apache.cocoon.caching.impl.CacheImpl  - Cache MISS for PK_G-aspect-cocoon://DRI/7/favicon.ico?pipelinehash=-1941327661434669097_T-Navigation-3212562138654597485

2016-02-16 00:35:50,783 INFO  org.apache.cocoon.caching.impl.CacheImpl  - Cache MISS for PK_G-aspect-cocoon://DRI/6/favicon.ico?pipelinehash=26815437322659760_T-SystemwideAlerts-1_T-Navigation--5367372201529954577

2016-02-16 00:35:50,783 INFO  org.apache.cocoon.caching.impl.CacheImpl  - Cache MISS for PK_G-aspect-cocoon://DRI/5/favicon.ico?pipelinehash=-4170905213321689863_T-Navigation-5799876941772906259

2016-02-16 00:35:50,783 INFO  org.apache.cocoon.caching.impl.CacheImpl  - Cache MISS for PK_G-aspect-cocoon://DRI/4/favicon.ico?pipelinehash=7562864311120640244

2016-02-16 00:35:50,783 INFO  org.apache.cocoon.caching.impl.CacheImpl  - Cache MISS for PK_G-aspect-cocoon://DRI/3/favicon.ico?pipelinehash=-1058144055897292008

2016-02-16 00:35:50,783 INFO  org.apache.cocoon.caching.impl.CacheImpl  - Cache MISS for PK_G-aspect-cocoon://DRI/2/favicon.ico?pipelinehash=-738220103570222181

2016-02-16 00:35:50,783 INFO  org.apache.cocoon.caching.impl.CacheImpl  - Cache MISS for PK_G-aspect-cocoon://DRI/1/favicon.ico?pipelinehash=147586322582675017_T-PageNotFound--242969834922413342

2016-02-16 00:35:50,783 INFO  org.apache.cocoon.caching.impl.CacheImpl  - Cache MISS for PK_G-file-cocoon://DRI/favicon.ico?pipelinehash=-4234072418721460733_T-IncludePageMeta--5280603869656992694_T-IncludePageMeta-7145676799531262490_T-IncludePageMeta-1889180249406810576_T-xslt-file:///E:/dspace/webapps/xmlui/themes/BSU/BSU.xsl_T-i18n-context://i18n/?en_US__S-xhtml-;doctype-public=-//W3C//DTD XHTML 1.0 Strict//EN;doctype-system=http://www.w3.org/TR/xhtml1/DTD/xhtml1-strict.dtd;encoding=UTF-8;indent=yes

2016-02-16 00:35:50,783 ERROR cocoon.handled  - Failed to process pipeline

...

The descending order of DRI/#/favicon.ico right before the pipeline error looks so odd to me. What is happening there?

Is it trying to find the favicon set up via page-structure.xsl? I suspect it is something else since every page load doesn't generate these logs. I don't know if it is related, but my dspace.cfg file has the following line which does not exist:

websvc.opensearch.faviconurl = http://www.dspace.org/images/favicon.ico

I don't think we are intentionally trying to make "opensearch" work. Could that be causing this error?

Also, I hope that page not found errors eventually get re-written to be more useful; in particular, printing the URL that 'could not be found' as part of the error message would be great. Not every failed to process pipeline output message deserves 1500 lines, IMHO -- particularly for most page not found errors I can imagine.

[Pottinger, Hardy J.]

Hi, Victor,

> Can I disable those error messages?

Certainly, you can set the loglevel for Cocoon here:

https://github.com/DSpace/DSpace/blob/dspace-5_x/dspace/config/log4j.properties#L83-L84

If you don't need the INFO messages, you can set this to WARN, FATAL or OFF instead. [1]

I actually just delete these log files via a cron job after a short window on most of our boxes... as the info is potentially useful in the short term, but useless after a day or two.

--Hardy

[1] https://logging.apache.org/log4j/2.x/manual/customloglevels.html

---

From: Victor [victor....@gmail.com]
Sent: Tuesday, February 16, 2016 3:18 PM
To: Pottinger, Hardy J.
Subject: Re: [dspace-tech] Understanding / Debugging "ERROR cocoon.handled - Failed to process pipeline"

Hi Hardy; I posted another update and here is a summary / a few more thoughts.

My latest suspicion is that the majority of errors I am finding are pertaining to a requests for 'page that doesn't exist' rather than problems in the pageNotFound algorithm or the XML breaking down.

Can I disable those error messages? The cocoon files can end up getting huge since our site is being actively crawled and sitemaps only end up being suggestions.

Typing in a bogus URL generates a huge message (1500 lines) about why the page couldn't be shown. E.g., a handle that doesn't exist.

This doesn't seem like it would be a new problem for sites to be crawled and have these massive files getting populated as a result. There were 36 instances of failed to process pipeline that occurred between midnight and 1 am today which if that pattern continues would be 1.2 million lines for a day logging page not found errors.

Did you have any other concerns about protodocument.xml since I found it in the official dspace files?

When I entered fake URLs, I can find them fairly easily but the ones that happen when presumably only crawlers are active look a little different in the INFO remarks before the stack trace.

Some examples are:

(these often show #s 9->1 just past DRI)

2016-02-16 00:39:00,754 INFO  org.apache.cocoon.caching.impl.CacheImpl  - Cache MISS for PK_G-aspect-cocoon://DRI/9/wordpress/wp-admin/?pipelinehash=477348137205522819_T-Navigation--5395830111285582982

2016-02-16 00:44:51,853 INFO  org.apache.cocoon.caching.impl.CacheImpl  - Cache MISS for PK_G-aspect-cocoon://DRI/9/blog/wp-admin/?pipelinehash=477348137205522819_T-Navigation-2792154001163817932

2016-02-16 00:55:34,972 INFO  org.apache.cocoon.caching.impl.CacheImpl  - Cache MISS for PK_G-aspect-cocoon://DRI/9/favicon.ico?pipelinehash=477348137205522819_T-Navigation-4797627539972478138

2016-02-16 00:56:21,520 INFO  org.apache.cocoon.caching.impl.CacheImpl  - Cache MISS for PK_G-aspect-cocoon://DRI/9/old/wp-admin/?pipelinehash=9065269893901859459

Oddly enough, they are predominantly favicon.ico showing up just before the error. But any ideas you may have on preventing this error would be much appreciated. Thanks!

  --Victor

[Feed My Lambs Esq.]

Thanks Hardy,

Where can I start looking for changing the inner mechanics for how the pagenotfound error should be handled? Shouldn't it be handled more gracefully?

Is there even a good reason to have a full stack trace / dump for pagenotfound errors?

Can anyone else confirm pagenotfound errors look the same way in your cocoon log (hundreds of lines long without explicitly stating what page was even requested)?

Do you also have a happily functioning system with dozens / hour of this kind of error in your cocoon log as well?

[Feed My Lambs Esq.]

I updated my dspace-api\pom.xml file to contain the changes you included here:

https://github.com/DSpace/DSpace/pull/1291/files

I added the code just before the maven-surefire-plugin.

I then ran "call mvn -e package" but didn't see any errors or comments about the validation tool. Does that mean all my XML is fine?

What would an error look like and what text does the confirmation that all is well say?