Re: [Tools-discuss] [www.ietf.org/rt #115169] Data tracker API failing with 'Internal Server Error'

["Fred Baker (fred)" <[e-mail]>]

Thanks.

Copying Glen, who has been working on this. Last week, there were a number of more-or-less-random failures, including server errors, gateways that were unreachable, and files not found. In the past couple of days, Glen has taken a look at it, and appears to have mostly resolved the issues. I have one remaining issue, which I'm tracking down as we speak so I can describe it to Glen. It goes something like this.

I have two scripts that I'm looking at. One wonders what drafts Cisco employees have in the pipeline (so we can inform various communities inside the company); the other wonders what subset of those have been updated since the past IETF meeting and are specifically working group draft, or are specifically individual submissions (because we get asked). Note that one of the two seems to invariably work, and is accessing essentially the same data. The script that asks about the more general set of drafts seems to mostly work, downloading state information etc and then moving on to downloading relevant draft metadata (I'd download the entire set of drafts in one swell foop, but there are more than 1000 drafts at any given time). I see this:

First, quite a number of perfectly normal and successful accesses (I'm showing you my debug output, which says what command I'm executing):

perl -w /users/fred/WWW/json/json-cisco-work.pl --wg --debug test --individual /users/fred/draft/.current > /users/fred/WWW/json/cisco-drafts.txt
accessing http://wwwin-people.cisco.com/fred/cisco_exceptions
accessing curl 'https://datatracker.ietf.org/api/v1/doc/state/?format=json&limit=0&type__slug__in=draft-rfceditor' 2> /dev/null
accessing curl 'https://datatracker.ietf.org/api/v1/doc/state/?format=json&limit=0&type__slug__in=draft-stream-ise' 2> /dev/null
accessing curl 'https://datatracker.ietf.org/api/v1/doc/state/?format=json&limit=0&type__slug__in=draft-iesg' 2> /dev/null
accessing curl 'https://datatracker.ietf.org/api/v1/doc/state/?format=json&limit=0&type__slug__in=draft-stream-ietf' 2> /dev/null
accessing curl 'https://datatracker.ietf.org/api/v1/group/group/?format=json&limit=0&type__slug__in=ietf' 2> /dev/null
accessing curl 'https://datatracker.ietf.org/api/v1/group/group/?format=json&limit=0&type__slug__in=area' 2> /dev/null
accessing curl 'https://datatracker.ietf.org/api/v1/group/group/?format=json&limit=0&type__slug__in=wg' 2> /dev/null
accessing curl 'https://datatracker.ietf.org/api/v1/group/group/?format=json&limit=0&type__slug__in=irtf' 2> /dev/null
accessing curl 'https://datatracker.ietf.org/api/v1/group/group/?format=json&limit=0&type__slug__in=rg' 2> /dev/null
accessing curl 'https://datatracker.ietf.org/api/v1/group/group/?format=json&limit=0&type__slug__in=ag' 2> /dev/null
accessing curl 'https://datatracker.ietf.org/api/v1/group/group/?format=json&limit=0&type__slug__in=iab' 2> /dev/null
accessing curl 'https://datatracker.ietf.org/api/v1/group/group/?format=json&limit=0&type__slug__in=dir' 2> /dev/null
accessing curl 'https://datatracker.ietf.org/api/v1/doc/document/?format=json&name__contains=draft-ietf-insipid-logme-reqs&limit=0' 2> /dev/null
accessing curl 'https://datatracker.ietf.org/api/v1/doc/state/1/?format=json' 2> /dev/null
accessing curl 'https://datatracker.ietf.org/api/v1/doc/document/?format=json&name__contains=draft-li-pce-tunnel-segment&limit=0' 2> /dev/null
accessing curl 'https://datatracker.ietf.org/api/v1/doc/document/?format=json&name__contains=draft-urien-core-racs&limit=0' 2> /dev/null
accessing curl 'https://datatracker.ietf.org/api/v1/doc/document/?format=json&name__contains=draft-ietf-avtcore-rtp-multi-stream-optimisation&limit=0' 2> /dev/null
accessing curl 'https://datatracker.ietf.org/api/v1/doc/document/?format=json&name__contains=draft-ietf-tcpm-accurate-ecn&limit=0' 2> /dev/null

I see probably 500 or more accesses for internet draft metadata similar to that last line, but for various drafts. And then I see:

accessing curl 'https://datatracker.ietf.org/api/v1/doc/document/?format=json&name__contains=draft-irtf-cfrg-xmss-hash-based-signatures&limit=0' 2> /dev/null
JSON text must be an object or array (but found number, string, true, false or null, use allow_nonref to allow this) at /users/fred/WWW/json/json-cisco-work.pl line 256

Note that this doesn't happen on any specific draft, just on some draft whose metadata I access. When I get curious about what it accessed, I get:

121:fred@irp-lnx1% curl 'https://datatracker.ietf.org/api/v1/doc/document/?format=json&name__contains=draft-irtf-cfrg-xmss-hash-based-signatures&limit=0'
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
{"meta": {"limit": 1000, "next": null, "offset": 0, "previous": null, "total_count": 1}, "objects": [{"abstract": "   This note describes the eXtended Merkle Signature Scheme (XMSS), a\n   hash-based digital signature system.  It follows existing\n   descriptions in scientific literature.  The note specifies the WOTS+\n   one-time signature scheme, a single-tree (XMSS) and a multi-tree\n   variant (XMSS^MT) of XMSS.  Both variants use WOTS+ as a main\n   building block.  XMSS provides cryptographic digital signatures\n   without relying on the conjectured hardness of mathematical problems.\n   Instead, it is proven that it only relies on the properties of\n   cryptographic hash functions.  XMSS provides strong security\n   guarantees and, besides some special instantiations, is even secure\n   when the collision resistance of the underlying hash function is\n   broken.  It is suitable for compact implementations, relatively\n   simple to implement, and naturally resists side-channel attacks.\n   Unlike most o105  1997  105  1997    0     0    142      0  0:00:14  0:00:13  0:00:01   410
ther signature systems, hash-based signatures withstand\n   attacks using quantum computers.\n", "ad": null, "authors": ["/api/v1/person/email/dbutin%40cdc.informatik.tu-darmstadt.de/", "/api/v1/person/email/stefan-lukas_gazdag%40genua.eu/", "/api/v1/person/email/ietf%40huelsing.net/", "/api/v1/person/email/mohaisen%40buffalo.edu/"], "expires": "2016-08-18T03:54:01", "external_url": "", "group": "/api/v1/group/group/1969/", "intended_std_level": null, "internal_comments": "", "name": "draft-irtf-cfrg-xmss-hash-based-signatures", "note": "", "notify": "", "order": 1, "pages": 56, "resource_uri": "/api/v1/doc/document/draft-irtf-cfrg-xmss-hash-based-signatures/", "rev": "03", "rfc": null, "shepherd": null, "states": ["/api/v1/doc/state/1/", "/api/v1/doc/state/58/"], "std_level": null, "stream": "/api/v1/name/streamname/ietf/", "tags": [], "time": "2016-02-15T03:54:01", "title": "XMSS: Extended Hash-Based Signatures", "type": "/api/v1/name/doctypename/draft/"}]}122:fred@irp-lnx1%

Which is to say that the json response is just fine, thank you very much.

What I conclude (what I think I am forced to conclude) is that SOMETIMES, for reasons that I haven't been able to nail down, I get a bogus json response. It's intermittent and not very repeatable for any given file, but its very repeatable at some point in a list as I walk through a long list of files. The other script (one being derived from the other, and very similar) accesses metadata for a shorter list of files (only the WG docs, or only the individual submissions, and only if it has been updated since November), so the issue might even be the length of the list of files for all I know.

If you have a clue as to how I might debug this or what information might be helpful to you or Glen, please advise.

> On Mar 16, 2016, at 10:49 AM, Henrik Levkowetz <[e-mail]> wrote:
> 
> Hi Fred,
> 
> You may already have seen the blurb for the latest datatracker release,
> but in case not, I've introduced some caching which should reduce the
> time it takes to produce REST API responses:
> 
>   https://datatracker.ietf.org/release/6.17.0/
> 
> It turns out that the API framework we are using has a weakness in how
> it deals with related objects, and this caused a doubling (approximately)
> of the response time for the groups query, even if the new related objects
> were 2 relationships away.  The caching I've coded up should deal with this,
> and my tests indicate an improvement with about a factor 4, or a factor 2
> better than before 6.16.0.
> 
> If, however, things still aren't working out for you, please let Glen,
> Robert and me know.
> 
> 
> Best regards,
> 
> 	Henrik
> 
> 
> On 2016-03-14 15:59, Fred Baker (fred) wrote:
>> The API to IETF data is still failing, just like it was a week ago. What is the plan for getting this fixed?
>> 
>> 104:fred@irp-lnx1% date;curl 'https://datatracker.ietf.org/api/v1/group/group/?format=json&limit=0&type__slug__in=wg'
>> Mon Mar 14 07:56:14 PDT 2016
>> <!DOCTYPE HTML PUBLIC "-//IETF//DTD HTML 2.0//EN">
>> <html><head>
>> <title>504 Gateway Timeout</title>
>> </head><body>
>> <h1>Gateway Timeout</h1>
>> <p>The gateway did not receive a timely response
>> from the upstream server or application.</p>
>> </body></html>
>> 
>> 
>>> On Mar 10, 2016, at 1:06 PM, Fred Baker (fred) <[e-mail]> wrote:
>>> 
>>> Would it help if I sent my script, perhaps? See attached. My model command is:
>>> 
>>> perl -w json-cisco-work.pl --wg --individual --debug test current > cisco-drafts.txt
>>> 
>>> You will need to change one access, which seeks to read http://wwwin-people.cisco.com/fred/cisco_exceptions; you can't get to it from outside Cisco. I have attached it as a file.
>>> 
>>> The debug option has it say what it is trying to read, giving you the option of repeating the access. In the output following, you will notice that it correctly accessed
>>> 
>>> "current" is a list of active internet drafts, derived from 1id-index.txt.
>>> 
>>> I ran the script twice, and got different results - something that has been an issue all through this. It seems to be able to correctly access a random number of json files, and then has some issue (in this case, "404 no such file", in other cases a gateway failure or an internal error) on which it chokes.
>>> 
>>> Note that this all worked until recently. This is not new code.
>>> 
>>> 119:fred@irp-lnx1% !nice
>>> nice csh /users/fred/WWW/json/new-work.sh 2015-10-20 2015-11-01 2016-03-27 November-March-2016
>>> accessing http://wwwin-people.cisco.com/fred/cisco_exceptions
>>> accessing curl 'https://datatracker.ietf.org/api/v1/doc/state/?format=json&limit=0&type__slug__in=draft-rfceditor' 2> /dev/null
>>> accessing curl 'https://datatracker.ietf.org/api/v1/doc/state/?format=json&limit=0&type__slug__in=draft-stream-ise' 2> /dev/null
>>> accessing curl 'https://datatracker.ietf.org/api/v1/doc/state/?format=json&limit=0&type__slug__in=draft-iesg' 2> /dev/null
>>> accessing curl 'https://datatracker.ietf.org/api/v1/doc/state/?format=json&limit=0&type__slug__in=draft-stream-ietf' 2> /dev/null
>>> accessing curl 'https://datatracker.ietf.org/api/v1/group/group/?format=json&limit=0&type__slug__in=ietf' 2> /dev/null
>>> accessing curl 'https://datatracker.ietf.org/api/v1/group/group/?format=json&limit=0&type__slug__in=area' 2> /dev/null
>>> accessing curl 'https://datatracker.ietf.org/api/v1/group/group/?format=json&limit=0&type__slug__in=wg' 2> /dev/null
>>> malformed JSON string, neither array, object, number, string or atom, at character offset 0 ["<!DOCTYPE HTML PUBLI..."] at json-cisco-new-work.pl line 171
>>> accessing http://wwwin-people.cisco.com/fred/cisco_exceptions
>>> accessing curl 'https://datatracker.ietf.org/api/v1/doc/state/?format=json&limit=0&type__slug__in=draft-rfceditor' 2> /dev/null
>>> accessing curl 'https://datatracker.ietf.org/api/v1/doc/state/?format=json&limit=0&type__slug__in=draft-stream-ise' 2> /dev/null
>>> accessing curl 'https://datatracker.ietf.org/api/v1/doc/state/?format=json&limit=0&type__slug__in=draft-iesg' 2> /dev/null
>>> accessing curl 'https://datatracker.ietf.org/api/v1/doc/state/?format=json&limit=0&type__slug__in=draft-stream-ietf' 2> /dev/null
>>> accessing curl 'https://datatracker.ietf.org/api/v1/group/group/?format=json&limit=0&type__slug__in=ietf' 2> /dev/null
>>> accessing curl 'https://datatracker.ietf.org/api/v1/group/group/?format=json&limit=0&type__slug__in=area' 2> /dev/null
>>> accessing curl 'https://datatracker.ietf.org/api/v1/group/group/?format=json&limit=0&type__slug__in=wg' 2> /dev/null
>>> malformed JSON string, neither array, object, number, string or atom, at character offset 0 ["<!DOCTYPE HTML PUBLI..."] at json-cisco-new-work.pl line 171
>>> 120:fred@irp-lnx1% date;curl 'https://datatracker.ietf.org/api/v1/group/group/?format=json&limit=0&type__slug__in=wg'
>>> Thu Mar 10 12:23:27 PST 2016
>>> 
>>> <!DOCTYPE html>
>>> 
>>> 
>>> 
>>> <html lang="en">
>>> <head>
>>>   <meta charset="utf-8">
>>>   <meta http-equiv="X-UA-Compatible" content="IE=edge">
>>>   <title>404 Not Found</title>
>>>   <meta name="viewport" content="width=device-width, initial-scale=1">
>>> 
>>>   <link href="https://www.ietf.org/lib/dt/6.16.0/ptmono/stylesheet.css" rel='stylesheet' type='text/css'>
>>>   <link href="https://www.ietf.org/lib/dt/6.16.0/ptsans/stylesheet.css" rel='stylesheet' type='text/css'>
>>>   <link href="https://www.ietf.org/lib/dt/6.16.0/ptserif/stylesheet.css" rel='stylesheet' type='text/css'>
>>> 
>>> ...
>>> 
>>> 
>>>> On Mar 10, 2016, at 12:12 PM, Matt Larson via RT <[e-mail]> wrote:
>>>> 
>>>> Hi Fred,
>>>> 
>>>> We've done some further tuning, and believe that this is resolved. Please let
>>>> me know if you have any further issues.
>>>> 
>>>> Matt
>>>> 
>>>> On Thu Mar 10 09:44:29 2016, [e-mail] wrote:
>>>>> 
>>>>>> On Mar 10, 2016, at 5:21 AM, Matt Larson via RT <ietf-
>>>>> [e-mail]> wrote:
>>>>>> 
>>>>>> Greetings,
>>>>>> 
>>>>>> I believe this has stabilized now that the server move is completed.
>>>>> I did some
>>>>>> testing and have been able to consistently pull that URL, along with
>>>>> a sampling
>>>>>> of the others.
>>>>>> 
>>>>>> I am going to resolve out this ticket, but please let us know if
>>>>> there are any
>>>>>> further issues. Replying to this email will re-open the ticket.
>>>>>> 
>>>>>> Matt
>>>>> 
>>>>> 105:fred@irp-lnx1% nice perl -w /users/fred/WWW/json/json-cisco-
>>>>> work.pl --wg --individual --debug test /users/fred/draft/.current >
>>>>> /users/fred/WWW/json/cisco-drafts.txt
>>>>> accessing http://wwwin-people.cisco.com/fred/cisco_exceptions
>>>>> accessing curl
>>>>> 
>>>> 'https://datatracker.ietf.org/api/v1/doc/state/?format=json&limit=0&type__slug__in=draft-
>>>>> rfceditor' 2> /dev/null
>>>>> accessing curl
>>>>> 
>>>> 'https://datatracker.ietf.org/api/v1/doc/state/?format=json&limit=0&type__slug__in=draft-
>>>>> stream-ise' 2> /dev/null
>>>>> accessing curl
>>>>> 
>>>> 'https://datatracker.ietf.org/api/v1/doc/state/?format=json&limit=0&type__slug__in=draft-
>>>>> iesg' 2> /dev/null
>>>>> accessing curl
>>>>> 
>>>> 'https://datatracker.ietf.org/api/v1/doc/state/?format=json&limit=0&type__slug__in=draft-
>>>>> stream-ietf' 2> /dev/null
>>>>> accessing curl
>>>>> 
>>>> 'https://datatracker.ietf.org/api/v1/group/group/?format=json&limit=0&type__slug__in=ietf'
>>>>> 2> /dev/null
>>>>> accessing curl
>>>>> 
>>>> 'https://datatracker.ietf.org/api/v1/group/group/?format=json&limit=0&type__slug__in=area'
>>>>> 2> /dev/null
>>>>> accessing curl
>>>>> 
>>>> 'https://datatracker.ietf.org/api/v1/group/group/?format=json&limit=0&type__slug__in=wg'
>>>>> 2> /dev/null
>>>>> malformed JSON string, neither array, object, number, string or atom,
>>>>> at character offset 0 ["<!DOCTYPE HTML PUBLI..."] at
>>>>> /users/fred/WWW/json/json-cisco-work.pl line 177
>>>>> 106:fred@irp-lnx1% date;curl
>>>>> 
>>>> 'https://datatracker.ietf.org/api/v1/group/group/?format=json&limit=0&type__slug__in=wg'
>>>>> Thu Mar 10 09:43:38 PST 2016
>>>>> <!DOCTYPE HTML PUBLIC "-//IETF//DTD HTML 2.0//EN">
>>>>> <html><head>
>>>>> <title>504 Gateway Timeout</title>
>>>>> </head><body>
>>>>> <h1>Gateway Timeout</h1>
>>>>> <p>The gateway did not receive a timely response
>>>>> from the upstream server or application.</p>
>>>>> </body></html>
>>>>> 
>>>>> 
>>>>> 
>>>>> 
>>>>> 
>>>>> 
>>>>> 
>>>>>> On Tue Mar 08 22:16:23 2016, [e-mail] wrote:
>>>>>>> Over the past few days (at least, I'm not sure when it started
>>>>>>> happening) I am randomly getting errors that look like this. Often
>>>>>>> several - tens or hundreds - of transactions will work and then one
>>>>>>> fail.
>>>>>>> 
>>>>>>> Suggestions?
>>>>>>> 
>>>>>>> 144:fred@irp-lnx1% curl
>>>>>>> 
>>>>>> 
>>>>> 
>>>> 'https://datatracker.ietf.org/api/v1/group/group/?format=json&limit=0&type__slug__in=wg'
>>>>>>> <!DOCTYPE HTML PUBLIC "-//IETF//DTD HTML 2.0//EN">
>>>>>>> <html><head>
>>>>>>> <title>500 Internal Server Error</title>
>>>>>>> </head><body>
>>>>>>> <h1>Internal Server Error</h1>
>>>>>>> <p>The server encountered an internal error or
>>>>>>> misconfiguration and was unable to complete
>>>>>>> your request.</p>
>>>>>>> <p>Please contact the server administrator at
>>>>>>> [e-mail] to inform them of the time this error
>>>>> occurred,
>>>>>>> and the actions you performed just before this error.</p>
>>>>>>> <p>More information about this error may be available
>>>>>>> in the server error log.</p>
>>>>>>> <p>Additionally, a 403 Forbidden
>>>>>>> error was encountered while trying to use an ErrorDocument to
>>>>> handle
>>>>>>> the request.</p>
>>>>>>> </body></html>
>>>>>>> 
>>>>>>> 
>>>>>>> My models, in case this is relevant:
>>>>>>> 
>>>>>>> 145:fred@irp-lnx1% fgrep datatracker.ietf.org
>>>>>>> /users/fred/WWW/json/json-cisco-work.pl
>>>>>>> "curl
>>>>>>> 
>>>>>> 
>>>>> 
>>>> 'https://datatracker.ietf.org/api/v1/doc/state/?format=json&limit=0&type__slug__in=draft-
>>>>>>> stream-ietf' 2> /dev/null";
>>>>>>> "curl
>>>>>>> 
>>>>>> 
>>>>> 
>>>> 'https://datatracker.ietf.org/api/v1/doc/state/?format=json&limit=0&type__slug__in=draft-
>>>>>>> iesg' 2> /dev/null";
>>>>>>> "curl
>>>>>>> 
>>>>>> 
>>>>> 
>>>> 'https://datatracker.ietf.org/api/v1/doc/state/?format=json&limit=0&type__slug__in=draft-
>>>>>>> rfceditor' 2> /dev/null";
>>>>>>> $curl_ise_rev = "curl
>>>>>>> 
>>>>>> 
>>>>> 
>>>> 'https://datatracker.ietf.org/api/v1/doc/state/?format=json&limit=0&type__slug__in=draft-
>>>>>>> stream-ise' 2> /dev/null";
>>>>>>> "curl
>>>>>>> 
>>>>>> 
>>>>> 
>>>> 'https://datatracker.ietf.org/api/v1/group/group/\?format=json&limit=0&type__slug__in=%s'
>>>>>>> 2> /dev/null";
>>>>>>> my $curl = "curl 'https://datatracker.ietf.org%s?format=json' 2>
>>>>>>> /dev/null";
>>>>>>> "curl
>>>>>>> 
>>>>>> 
>>>>> 
>>>> 'https://datatracker.ietf.org/api/v1/doc/document/\?format=json\&name__contains=%s\&limit=0'
>>>>>>> 2> /dev/null";
>>>>>>> "curl 'https://datatracker.ietf.org%s\?format=json' 2>
>>>>>>> /dev/null";
>>> 
>>> <json-cisco-work.pl><current><cisco_exceptions>
>> 
>> 
>> 
>