Intermittent 500s

[msabramo]

Sometimes the same call succeeds and sometimes it returns a 500 error that looks like this:

________________________________________________________________ TestDocverter.test_basic_conversion_from_file _________________________________________________________________
test_docverter.py:51: in test_basic_conversion_from_file
    received = docverter.convert(file_name, 'rst')
docverter.py:28: in convert
    format, extra_args, encoding=encoding)
docverter.py:60: in _convert
    return processor(source, to, format, extra_args)
docverter.py:96: in _process_file
    % (resp, resp.content))
E   RuntimeError: Call to docverter failed - 
    resp = <Response [500]>; 
    resp.content = '{"error":"No such file or directory - tmpkElYDL"}'

[msabramo]

Another one:

_______________________________________________________________ TestDocverter.test_basic_conversion_from_string ________________________________________________________________
test_docverter.py:74: in test_basic_conversion_from_string
    received = docverter.convert('#some title', 'rst', format='md')
docverter.py:28: in convert
    format, extra_args, encoding=encoding)
docverter.py:60: in _convert
    return processor(source, to, format, extra_args)
docverter.py:96: in _process_file
    % (resp, resp.content))
E   RuntimeError: Call to docverter failed - 
    resp = <Response [500]>; 
    resp.content = b'{"error":"No such file or directory - manifest.orig.yml"}'

[msabramo]

Another; the error is slightly different in this one.

<Response [500]>;
resp.content = '{"error":"command error: pandoc: tmpqBtaRr: openFile: does not exist 
                  (No such file or directory)\\n"}'

[peterkeen]

Are you using the pubic instance or your own instance?

[msabramo]

Public. c.docverter.com

[msabramo]

Maybe I'll see if I can reproduce on a self-hosted instance.

[msabramo]

Hmmm. Maybe it's a bug in my Python code (I'm writing a Python client for Docverter), because I can't reproduce with HTTPie.

❯ while true; do http --form -f POST http://c.docverter.com/convert from=markdown to=rst 'input_files[]@/tmp/tmpqBtaRr' --print=h --pretty=none | grep '^HTTP'; sleep 1; done
HTTP/1.1 200 OK
HTTP/1.1 200 OK
HTTP/1.1 200 OK
HTTP/1.1 200 OK
HTTP/1.1 200 OK
HTTP/1.1 200 OK
HTTP/1.1 200 OK
HTTP/1.1 200 OK
HTTP/1.1 200 OK
HTTP/1.1 200 OK
HTTP/1.1 200 OK
HTTP/1.1 200 OK
HTTP/1.1 200 OK
HTTP/1.1 200 OK
HTTP/1.1 200 OK
HTTP/1.1 200 OK
HTTP/1.1 200 OK
HTTP/1.1 200 OK
HTTP/1.1 200 OK
HTTP/1.1 200 OK
HTTP/1.1 200 OK
HTTP/1.1 200 OK
HTTP/1.1 200 OK
HTTP/1.1 200 OK
HTTP/1.1 200 OK
HTTP/1.1 200 OK
HTTP/1.1 200 OK
HTTP/1.1 200 OK
HTTP/1.1 200 OK
HTTP/1.1 200 OK

Though it seems to me like those temp file errors are happening on the server, because the filenames don't match the temp file filenames that my program is using.

[peterkeen]

Hm. The only time the server makes a new filename is when it's encrypting a PDF. The rest of the time it's working with the given filenames in a tempdir.

[msabramo]

Maybe those temp files are being created by the web server and then being passed into the Ruby code?

[peterkeen]

For both input_files[] and other_files[] we copy the given tempfile handle to the original given filename:

https://github.com/Docverter/docverter/blob/master/lib/docverter-server/app.rb#L20-L27

We have to do this because your input files are going to refer each other and to things in other_files[] by filename.

[msabramo]

Hmmm. IIRC from my PHP days, sometimes the web server or the platform will keep uploaded files in memory (especially if the files are small and mine are) and not always write them to a temp file on the disk.

[peterkeen]

It doesn't really matter. The :tempfile key in the upload is something that responds to read and the :filename key is the filename specified by the MIME header for that part of the request.

Also, in almost three years of development this is the first time someone has mentioned a bug like this, which makes me think the problem is not necessarily in Docverter. It may be a weird combination of edge cases, though.

[msabramo]

Yeah, this is weird. I have not seen it yet with HTTPie and it is sporadic when running my Python test suite. I have gotten it to happen a few times when running the tests locally, though it seems anecdotally to happen more when running tests on Travis CI. But it's not exclusive to Travis CI.

[msabramo]

Here's a dump of the HTTP request for a recent failure:

POST http://c.docverter.com/convert
Content-Length: 345
Content-Type: multipart/form-data; boundary=03377687359d44d78a5e88a807d085aa
--03377687359d44d78a5e88a807d085aa
Content-Disposition: form-data; name="from"
markdown
--03377687359d44d78a5e88a807d085aa
Content-Disposition: form-data; name="to"
rst
--03377687359d44d78a5e88a807d085aa
Content-Disposition: form-data; name="input_files[]"; filename="tmpCg8ugv"
#some title
--03377687359d44d78a5e88a807d085aa--

The response was a 500 with:

No such file or directory - /tmp/d20150202-3-fx2rd3/output.dab677eb282d3aa6ec5e.rst

Interesting - for this one - the error is with the output file (note the .rst extension); not the input file.

[peterkeen]

Thank you for the dump. I'm seeing occasional Heroku errors in the logs, but it doesn't look like they're related to this problem. I'll dig into it when I have time.

[msabramo]

Cool and thank you for creating Docverter! I was about to embark on something similar and then I found this. Pretty exited about it! Thank you for sharing it with the world!

[msabramo]

Here's a full request and response from Wireshark for when you get a chance to look into this:

POST /convert HTTP/1.1
Host: c.docverter.com
Accept-Encoding: identity
Content-Length: 345
Content-Type: multipart/form-data; boundary=72cc0e21ba084ae487aa61ea147bf1b7

--72cc0e21ba084ae487aa61ea147bf1b7
Content-Disposition: form-data; name="to"

rst
--72cc0e21ba084ae487aa61ea147bf1b7
Content-Disposition: form-data; name="from"

markdown
--72cc0e21ba084ae487aa61ea147bf1b7
Content-Disposition: form-data; name="input_files[]"; filename="tmpkZmEM6"

#some title

--72cc0e21ba084ae487aa61ea147bf1b7--
HTTP/1.1 500 Server Error
Server: Cowboy
Date: Mon, 02 Feb 2015 17:21:29 GMT
Connection: close
Content-Type: application/json
Via: 1.1 vegur

{"error":"No such file or directory - /tmp/d20150202-3-13s56rr/output.b4a5a6e75446083707f4.rst"}

[msabramo]

I am wondering if we are running into an issue with IO.popen and buffering -- e.g.: http://stackoverflow.com/questions/7117088/ruby-io-popen-stdout-buffering

In https://github.com/Docverter/docverter/blob/master/lib/docverter-server/runner/base.rb#L23:

        IO.popen(cmd) do |io|
          output = io.read
        end

Perhaps this completes without pandoc getting a chance to write its output, especially since the command-line has 2>&1 in it, so it's going to have to launch a shell process and the shell process will own pandoc. Perhaps the shell exits before pandoc does and so the Ruby code thinks pandoc is done but it's not.

[msabramo]

#30 is a stab at hacking around this problem.

[msabramo]

Any luck reproducing this on your end?

[peterkeen]

I pushed your change to the demo server. Are you still seeing this error?

On Thu, Feb 12, 2015 at 11:08 AM, Marc Abramowitz [email protected]
wrote:

Any luck reproducing this on your end?

—
Reply to this email directly or view it on GitHub
#28 (comment).

[msabramo]

Unfortunately yes. I just ran a Travis CI job and it failed again.

https://travis-ci.org/msabramo/pydocverter/builds/49901313

I also got one of these while running tests on my laptop:

=================================================================================== FAILURES ===================================================================================
________________________________________________________________ TestDocverter.test_basic_conversion_from_file _________________________________________________________________
test_docverter.py:51: in test_basic_conversion_from_file
    received = docverter.convert(file_name, 'rst')
docverter.py:28: in convert
    format, extra_args, encoding=encoding)
docverter.py:60: in _convert
    return processor(source, to, format, extra_args)
docverter.py:111: in _process_file
    % (resp, resp.content))
E   RuntimeError: Call to docverter failed - resp = <Response [503]>; resp.content = b'<!DOCTYPE html>\n    <html>\n    <head>\n      <meta name="viewport" content="width=device-width, initial-scale=1">\n      <style type="text/css">\n        html, body, iframe { margin: 0; padding: 0; height: 100%; }\n        iframe { display: block; width: 100%; border: none; }\n      </style>\n    <title>Application Error</title>\n    </head>\n    <body>\n      <iframe src="//s3.amazonaws.com/heroku_pages/error.html">\n        <p>Application Error</p>\n      </iframe>\n    </body>\n    </html>'

[msabramo]

I wonder if you're seeing the results of this statement in your server logs:

puts "Failed to open #{output_file}; num_tries = #{num_tries}"

?

[kmctown]

I ran into this as well. The problem is Dir.chdir is not thread safe and this will happen with threaded web servers. Fixed it by removing the Dir.chdir call at the top of /convert and passed in absolute file paths to manifest.