qastaging and staging librarians do not forward restricted requests to the master librarian

[Gary Poster]

For a relatively recent MP (https://code.staging.launchpad.net/~gary/launchpad/bug650343/+merge/37633/+index):

https://lp-oops.canonical.com/oops.py/?oopsid=OOPS-1752S202
https://lp-oops.canonical.com/oops.py/?oopsid=OOPS-1753S127

For an older MP, after LOSAs increased the hard_timeout for the page (https://code.staging.launchpad.net/~gary/launchpad/bug538236/+merge/22276):

https://lp-oops.canonical.com/oops.py/?oopsid=OOPS-1753S160

(Note that these exceptions are not being grouped by the OOPS tool.)

The librarian is working for bug attachments, like the patch on https://bugs.staging.launchpad.net/launchpad-foundations/+bug/534399 but that apparently uses a different mechanism.

[Gary Poster (gary)]

Notes...

Here's an example of the librarian's log for an instance of the first one (https://lp-oops.canonical.com/oops/?oopsid=OOPS-1753S156):

2010-10-19 15:37:21+0000 [-] Starting factory <twisted.web.proxy.ProxyClientFactory instance at 0x61b6fc8>
2010-10-19 15:37:21+0000 [ProxyClient,client] 91.189.90.174 - - [19/Oct/2010:15:37:20 +0000] "GET /57500648/e47a938c-d605-11df-88ae-001e0bc3957e.txt HTTP/1.0" 404 146 "-" "Python-urllib/2.6"
2010-10-19 15:37:21+0000 [ProxyClient,client] Stopping factory <twisted.web.proxy.ProxyClientFactory instance at 0x61b6fc8>

The second one:

2010-10-19 15:39:46+0000 [-] Starting factory <twisted.web.proxy.ProxyClientFactory instance at 0x5efc8c0>
2010-10-19 15:39:47+0000 [ProxyClient,client] 91.189.90.174 - - [19/Oct/2010:15:39:46 +0000] "GET /42395443/tdGJABsFQRvCCFlFQFUZlZSJOd9.txt HTTP/1.0" 404 146 "-" "Python-urllib/2.6"
2010-10-19 15:39:47+0000 [ProxyClient,client] Stopping factory <twisted.web.proxy.ProxyClientFactory instance at 0x5efc8c0>

I'm not sure yet what that buys me, other than being potentially interesting that it doesn't report an error. I don't understand why the ProxyClientFactory is starting and stopping yet.

mbarnett helped me use the second one as verification that the database tables are up to date on staging: the following query did return the appropriate value on staging, identical to production.

SELECT LibraryFileAlias.content, LibraryFileAlias.date_created, LibraryFileAlias.expires, LibraryFileAlias.filename, LibraryFileAlias.hits, LibraryFileAlias.id, LibraryFileAlias.last_accessed, LibraryFileAlias.mimetype, LibraryFileAlias.restricted FROM LibraryFileAlias, LibraryFileContent WHERE LibraryFileAlias.content = LibraryFileContent.id AND LibraryFileAlias.id = 42395443 AND LibraryFileAlias.restricted = True

https://pastebin.canonical.com/38822/

That query mirrors the search done in lib/canonical/librarian/db.py, in Library.getAlias, after the token code that should not be pertinent in this case.

        alias = LibraryFileAlias.selectOne(AND(
            LibraryFileAlias.q.id==aliasid,
            LibraryFileAlias.q.contentID==LibraryFileContent.q.id,
            LibraryFileAlias.q.restricted==restricted,
            ))
        if alias is None:
            raise LookupError("No file alias with LibraryFileContent")
        return alias

So, that LookupError shouldn't be the one triggering a 404.

The only other reasonable possibility for a 404 seem to be if the hostname does not match up (see canonical/librarian/web.py in LibraryFileAliasResource .getChild in the block that includes "if '.restricted.' in hostname:"). I think we'll need to add some logging to investigate that, so I'll do that next.

The other possibilities in web.py are if the alias is not an int (it is, 42395443) or if the dbname is not the same as what came in the request (it is, tdGJABsFQRvCCFlFQFUZlZSJOd9.txt).

So, I'm hoping it is that hostname thing.

[Tim Penhey (thumper)]

I can't think of anything that the merge proposal is doing that is special.

[Launchpad QA Bot (lpqabot)]

r11797 in stable (http://bazaar.launchpad.net/~launchpad-pqm/launchpad/stable/revision/11797) is part of this bug's fix.

[Gary Poster (gary)]

Developments:

- qastaging is exhibiting the same behavior. (staging is dead because of a failed restore; I've investigated that separately.)

- The logging code is now in place. I can verify by seeing "Using upstream librarian http://launchpadlibrarian.net:80" in the log output.

- The logging code indicates that the 404 is not caused by any of the problems I logged. It's the same as before.

2010-10-27 16:17:57+0000 [-] Starting factory <twisted.web.proxy.ProxyClientFact
ory instance at 0x76c6560>2010-10-27 16:17:57+0000 [ProxyClient,client] 91.189.90.174 - - [27/Oct/2010:16:
17:56 +0000] "GET /42395443/tdGJABsFQRvCCFlFQFUZlZSJOd9.txt HTTP/1.0" 404 146 "-
" "Python-urllib/2.6"
2010-10-27 16:17:57+0000 [ProxyClient,client] Stopping factory <twisted.web.prox
y.ProxyClientFactory instance at 0x76c6560>

Again, that's a file that seems to match up just fine with the SQL query we ran in comment 1.

Therefore, I'm left with exploring what the ProxyClientFactory is, and seeing if it might have anything to do with this (because I don't see that part of the log in devel); and then re-checking the SQL results.

[Gary Poster (gary)]

ProxyClientFactory was the trick.

Apparently, we don't have the librarian files on staging, unless the diff is made. We forward to production with a proxy. In c/librarian/web.py:

        if self.storage.hasFile(dbcontentID) or self.upstreamHost is None:
            ...
        else:
            return proxy.ReverseProxyResource(self.upstreamHost,
                                              self.upstreamPort, request.path)

I verified with a LOSA that self.storage.hasFile(dbcontentID) returns True on production for the main example I've been using for this debugging, and False on staging.

That ReverseProxyResource is not set up to handle restricted files. To make MPs work on staging, I think that's what needs to happen. That would be relatively easy to do, given the current structure. However, lifeless warns that the new token story may change the solution; also, we may want to completely change MPs' usage of the librarian to make it not proxy through Zope. So we should just hold off on this.

It seems likely that MPs on staging that have been copied over from production have not worked since they started using the restricted librarian.

Lifeless points out that a reasonable work-around for doing QA is to push a new branch to qastaging/staging. Then the file will be local, and everything will work.

Because there is a workaround, and because the way forward is not clear, I'm marking this low and taking myself off of it.

[Robert Collins (lifeless)]

Gary, a data point for you - the qastaging environment was using the
staging librarian. ENotGonnaWork.

-Rob

[Gary Poster (gary)]

Cool. I was primarily using the staging one for my tests in this case, and was able to use that to QA the original issue. I take it that qastaging's use of the staging librarian is already addressed?

[Robert Collins (lifeless)]

On Wed, Nov 3, 2010 at 2:56 AM, Gary Poster <email address hidden> wrote:
> Cool.  I was primarily using the staging one for my tests in this case,
> and was able to use that to QA the original issue.  I take it that
> qastaging's use of the staging librarian is already addressed?

Config change has been made and landed, yes. Dunno if it was your
issue or not, but likely related:)

[Gary Poster (gary)]

Not the same issue--this issue is simply that the capability of the librarian to proxy other librarians needs to support restricted files, or be replaced entirely with another solution--but the config change is appreciated nonetheless.

[Robert Collins (lifeless)]

I've tagged this easy - there are two ways forward:
A: permit the staging librarian to forward to the prod librarian
 - either an unchecked restricted request path (e.g. ask for a restricted file on the private port)
 - or issue tokens from the prod librarian and redirect to there

I think the first option will work best given the current layout of things

B: model which instance the file is in, and have urls and requests generated appropriately. (Also needs token issuing support).