Anansi sometimes fails to follow 303 redirects

[townxelliot]

If Anansi is asked to crawl a URI which returns a 303 redirect to a representation of the resource, the redirect is sometimes ignored. On other occasions, the redirect is queued and the resource is fetched. I couldn't discern any pattern to this behaviour.

The environment where I noted this behaviour is the Acropolis docker stack, and can be reproduced as follows:

1. Clone and run the Acropolis docker stack, so you have a running Anansi. See https://github.com/bbcarchdev/acropolis for instructions. The short version is docker-compose build inside a clone of the Anansi project.
2. Seed Anansi with a non-information resource URI which redirects to an information resource URI, e.g. http://dbpedia.org/resource/Dracula. The command for doing this with the docker stack is:

   docker exec acropolis_anansi_1 /usr/bin/crawler-add -f http://dbpedia.org/resource/Dracula
   

   You may need to repeat this command several times, as Anansi will sometimes follow the redirect correctly. Repeat until Anansi doesn't follow the redirect, effectively ignoring the resource you seeded it with. There is no information in the log about what has happened: the resource URI appears to be getting queued but is never processed.

[rjpwork]

What are we expecting to happen in the "success" case? eg. on that attempt, it fetched Dracula.xml but then rejected it for license reasons.

anansi_1         | crawld[1]: LOD: examining <http://dbpedia.org/data/Dracula.xml> for licensing triples
anansi_1         | crawld[1]: %ANANSI-I-3100: REJECTED <http://dbpedia.org/data/Dracula.xml>: (LOD: no suitable licensing triple)
anansi_1         | crawld[1]: RDF: filter declined further processing of this resource

[rjpwork]

On the second attempt, it didn't attempt to fetch Dracula.xml but that's possibly down to there being an entry for it in crawl_resource with REJECTED.

Indeed, deleting that record makes it fetch Dracula.xml again by following the redirect but then still rejects it via the LOD filter.

[townxelliot]

I'll provide some more thorough steps to reproduce the issue tomorrow. When I was trying this before Christmas, I either got a silent failure or successful processing of the resource (I don't get a rejection due to licence as far as I remember).

[rjpwork]

Ta. It's difficult to see what the intended result should be when it's logging that it's skipped the redirect at the same time as processing the result of the damned redirect.

[rjpwork]

Do we want to special case 303 as a follow then? Since the code currently blocks them in a few places with this conditional:

if(status > 300 && status < 304) { return /* variants on SKIPPED */; }

[nevali]

301, 302 and 303 should all be treated equivalently (although in future it would be a nice-to-have to set a different TTL depending upon which kind of redirect it was); from Anansi's point of view there's no reason why 303 ought to be special-cased. If there's a problem with 303 redirect handling, then it'll also apply to 301s and 302s too.

The intended for result should be:

If status is (301, 302, 303) then

• examine the Location header and queue the URL it contains
• end processing of this resource, setting the status to SKIPPED (logging the message as we go)

Given a database empty besides the redirecting resource, this ought to result in the redirect target being queued, fetched, and processed almost immediately after the skip has occurred (allowing for root minimum fetch times). Note that the skip is logged at a different level than accepted/rejected because redirects just clutter the logs, so it may not be immediately obvious that this is what has occurred.

[rjpwork]

Given a single URI which provides a 303 return that points to a valid RDF file (with nothing else to crawl), we expect

1. An entry in the database for the original URI, marked SKIPPED
2. An entry in the database for the redirected URI, marked ACCEPTED

Is that right?

[nevali]

Given a single URI which provides a 303 return, we expect

1. an entry in the database for the original URI, marked SKIPPED
2. an entry in the database for the redirect target URI, marked NEW, unless the redirect is to the original URI.

Tests like this should generally be executed in one-shot mode (-t).

At this point we know what the two URIs are (and whether they differ), and whether the target URI was successfully added.

Then, on a subsequent fetch, assuming the redirect target was indeed NEW and the resource is acceptable, we'd expect it to be marked ACCEPTED. As we have no particular need to test the basic operation of the database-based queue at this point (which would accounting for root TTLs and generally making things more complicated), you can further test that by executing another one-shot crawl of the target URI and retrieving the status from the database.

However, all this latter part is really testing is "is the fetch of the target URI somehow dependent upon the fetch of the original URI in any fashion other than fetching one triggering the existence in the queue of the other" — as that's not something we have any particular need to test for, I wouldn't bother with that, either.

Therefore we can do a one-shot test with the conditions at the top of this comment.

How's that?

[rjpwork]

Currently it is not performing step 2 for http://sws.geonames.org/2643743/ which is a 303 to http://sws.geonames.org/2643743/about.rdf. I can't see any obvious reason for this in the logs though.

[nevali]

My logs suggest the early bail-out from the curl receiver callback is throwing a spanner in the works and the request ends up being treated as a failure instead:

crawld: [Debug] Fetching http://sws.geonames.org/2643743/
* About to connect() to sws.geonames.org port 80 (#0)
*   Trying 188.40.33.19...
* connected
* Connected to sws.geonames.org (188.40.33.19) port 80 (#0)
> GET /2643743/ HTTP/1.1
Host: sws.geonames.org
Accept: application/rdf+xml;q=1.0, text/rdf;q=0.6, application/n-triples;q=1.0, text/plain;q=0.1, text/turtle;q=1.0, application/x-turtle;q=1.0, application/turtle;q=1.0, text/n3;q=0.3, text/rdf+n3;q=0.3, application/rdf+n3;q=0.3, application/x-trig;q=1.0, text/x-nquads;q=1.0, */*;q=0.1
User-Agent: Mozilla/5.0 (compatible; Anansi; libcrawl; +https://bbcarchdev.github.io/res/)

* additional stuff not fine transfer.c:1037: 0 0
* HTTP 1.1 or later with persistent connection, pipelining supported
< HTTP/1.1 303 See Other
< Date: Thu, 26 Jan 2017 10:32:20 GMT
< Server: Apache/2.4.6 (Linux/SUSE)
< Location: http://sws.geonames.org/2643743/about.rdf
< Content-Length: 333
< Content-Type: text/html; charset=iso-8859-1
< 
* Failed writing body (0 != 333)
* Closing connection #0
* Failed writing received data to disk/application
crawld: [Debug] DB: UPDATE "crawl_resource" SET "updated" = '2017-01-26 10:32:15', "last_modified" = '2017-01-26 10:32:15', "status" = 303, "crawl_instance" = NULL, "state" = 'FAILED' WHERE "hash" = '2a6e9d9958f8fddc6957dd7147601663'
crawld: [Debug] DB: UPDATE "crawl_resource" SET "next_fetch" = '2017-01-27 10:32:15' WHERE "hash" = '2a6e9d9958f8fddc6957dd7147601663' AND "next_fetch" < '2017-01-27 10:32:15'
crawld: [Debug] DB: UPDATE "crawl_root" SET "last_updated" = '2017-01-26 10:32:15' WHERE "hash" = '6dccbc6dbe6d1921c6f914bb75af3493'
crawld: [Debug] DB: UPDATE "crawl_root" SET "earliest_update" = '2017-01-26 10:32:15' WHERE "hash" = '6dccbc6dbe6d1921c6f914bb75af3493' AND "earliest_update" < '2017-01-26 10:32:15'
crawld: [Debug] DB: UPDATE "crawl_resource" SET "error_count" = 0, "soft_error_count" = 0 WHERE "hash" = '2a6e9d9958f8fddc6957dd7147601663'
crawld: Notice: %ANANSI-N-2034: crawl thread terminating [dev] crawler 1/1 (thread 1/1)
crawld: Notice: %ANANSI-N-2026: terminating crawl threads...
crawld: %ANANSI-I-2027: waiting for crawl threads to terminate...
crawld: Notice: %ANANSI-N-2028: all crawl threads have stopped

[rjpwork]

If you change the if(*status >= 300 && *status < 400) line in crawler/policy.c to allow 303 statuses, then it works fine for that URI - it gets added as SKIPPED and the .../about.rdf gets added to the queue and then eventually ACCEPTED.

Which implies it isn't anything to do with early bail-outs.

[nevali]

Early bail-outs happen because of that code (that's what—as the preceding comment indicates—the checkpoint callback is for)...

You seem to be saying that by changing the code to not return COS_SKIPPED, the result is that it gets set as SKIPPED in the queue, which is obviously undesirable, but it's hard to see what the effect of that is without the output of crawld -t URI with that change in place.

[nevali]

From the code, though, it should result in COS_SKIPPED being returned due to the content-type not matching the whitelist (as Geonames returns a text/html response), rather than the response code, but I can't see an obvious reason why returning COS_SKIPPED due to one rather than the other should make a difference.

[nevali]

workaround in e7d47c7