HTTP input is failing during simple POST test with multiple JSON lines

[bradvido]

I'm considering using this input, and I wanted to test it before committing to it.

Here's what I found;

Simple Java test:
This HTTP POSTs JSON lines (starting at 300, increasing by 1 until it fails) to the Logstash http input.

import java.io.BufferedReader;
import java.io.InputStreamReader;
import java.io.Reader;
import java.net.HttpURLConnection;
import java.net.URL;
import java.util.logging.Level;

public class HTTPInputTest {

    public static void main(String[] args) {
        try {
            String sampleJsonObj = "{\"glossary\":{\"title\":\"example glossary\",\"GlossDiv\":{\"title\":\"S\",\"GlossList\":{\"GlossEntry\":{\"ID\":\"SGML\",\"SortAs\":\"SGML\",\"GlossTerm\":\"Standard Generalized Markup Language\",\"Acronym\":\"SGML\",\"Abbrev\":\"ISO 8879:1986\",\"GlossDef\":{\"para\":\"A meta-markup language, used to create markup languages such as DocBook.\",\"GlossSeeAlso\":[\"GML\",\"XML\"]},\"GlossSee\":\"markup\"}}}}}";
            HttpSender h = new HttpSender();
            for (int num = 300; num < 10_000; num++) {
                String payload = "";
                for (int i = 0; i < num; i++) {
                    payload += sampleJsonObj + "\n";
                }
                byte[] bytes = payload.getBytes("UTF-8");
                System.out.println("Sending " + num + " lines, " + bytes.length + " bytes");
                h.post(bytes);
                Thread.sleep(100);//breathing room
            }
        } catch (Throwable t) {
            java.util.logging.Logger.getLogger(HTTPInputTest.class.getName()).log(Level.SEVERE, "Error!", t);
        }
    }

    private static class HttpSender {

        private final String lsHttpInput = "http://127.0.0.1:8888";

        public void post(byte[] postDataBytes) throws Exception {
            URL url = new URL(lsHttpInput);
            HttpURLConnection conn = (HttpURLConnection) url.openConnection();
            conn.setRequestMethod("POST");
            conn.setRequestProperty("Content-Type", "application/json");
            conn.setRequestProperty("Content-Length", String.valueOf(postDataBytes.length));
            conn.setDoOutput(true);
            conn.getOutputStream().write(postDataBytes);

            try (Reader in = new BufferedReader(new InputStreamReader(conn.getInputStream(), "UTF-8"))) {
                for (int c; (c = in.read()) >= 0;) {
                    System.out.print((char) c);
                }
            }
            System.out.println("");
        }
    }
}

Logstash 2.3.2 Config:

input { 
    http {
        host => "127.0.0.1"
        port => 8888
    }
} 
output { 
    null{} 
}

Results from running test:

Sending 300 lines, 108300 bytes
ok
Sending 301 lines, 108661 bytes
ok
Sending 302 lines, 109022 bytes
ok
Sending 303 lines, 109383 bytes
ok
Sending 304 lines, 109744 bytes
ok
Sending 305 lines, 110105 bytes
ok
Sending 306 lines, 110466 bytes
ok
Sending 307 lines, 110827 bytes
ok
Sending 308 lines, 111188 bytes
ok
Sending 309 lines, 111549 bytes
ok
Sending 310 lines, 111910 bytes
ok
Sending 311 lines, 112271 bytes
ok
Sending 312 lines, 112632 bytes
ok
Sending 313 lines, 112993 bytes
ok
Sending 314 lines, 113354 bytes
ok
Sending 315 lines, 113715 bytes
ok
Sending 316 lines, 114076 bytes
ok
Sending 317 lines, 114437 bytes
ok
Sending 318 lines, 114798 bytes
ok
Sending 319 lines, 115159 bytes
May 05, 2016 4:52:27 PM HTTPInputTest main
SEVERE: Error!
java.io.IOException: Server returned HTTP response code: 500 for URL: http://127.0.0.1:8888
    at sun.net.www.protocol.http.HttpURLConnection.getInputStream0(HttpURLConnection.java:1840)
    at sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1441)
    at dedot.HTTPInputTest$HttpSender.post(HTTPInputTest.java:44)
    at dedot.HTTPInputTest.main(HTTPInputTest.java:23)

Log output from Logstash:

io/console not supported; tty will not be manipulated
Settings: Default pipeline workers: 4
Pipeline main started
2016-05-05 20:28:31 -0500: Read error: #<Errno::ENOENT: No such file or directory - J:/tmp>
org/jruby/RubyFile.java:902:in `stat'
J:/admin/logstash/logstash-2.3.2/vendor/jruby/lib/ruby/shared/tmpdir.rb:33:in `tmpdir'
org/jruby/RubyArray.java:1613:in `each'
J:/admin/logstash/logstash-2.3.2/vendor/jruby/lib/ruby/shared/tmpdir.rb:30:in `tmpdir'
J:/admin/logstash/logstash-2.3.2/vendor/jruby/lib/ruby/shared/tmpdir.rb:109:in `tmpdir'
J:/admin/logstash/logstash-2.3.2/vendor/jruby/lib/ruby/shared/tmpdir.rb:141:in `create'
org/jruby/ext/tempfile/Tempfile.java:95:in `initialize19'
org/jruby/RubyIO.java:853:in `new'
J:/admin/logstash/logstash-2.3.2/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/client.rb:140:in `setup_body'
J:/admin/logstash/logstash-2.3.2/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/client.rb:178:in `try_to_finish'
J:/admin/logstash/logstash-2.3.2/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/client.rb:101:in `reset'
J:/admin/logstash/logstash-2.3.2/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/server.rb:414:in `process_client'
J:/admin/logstash/logstash-2.3.2/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/server.rb:270:in `run'
org/jruby/RubyProc.java:281:in `call'
J:/admin/logstash/logstash-2.3.2/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/thread_pool.rb:106:in `spawn_thread'

[jsvd]

hi, thanks for the report!
can you show the command line used to launch logstash?
looking at puma code (the web server we use), if the body hits a certain size then a temporary file is used to store it, and it seems that at that point logstash is unable to write to what ruby considers the OS's temp directory with the Tempfile class, in my windows laptop it's:

irb(main):004:0> Tempfile.new("test").path
=> "C:/Users/Jsvd/AppData/Local/Temp/test20160506-7620-1eugd11"

I guess we can try to prevent puma from doing this, but the alternative is checking if your J:/tmp could/should be readable.

[bradvido]

This definitely seems to be a problem with trying to create a temp dir. I'm on Windows 10 laptop.

To debug ruby, I added some output to the Dir::tmpdir function in the tmpdir.rb file:

  def Dir::tmpdir
    if $SAFE > 0
      tmp = @@systmpdir
    else
      # Search a directory which isn't world-writable first. In JRuby,
      # FileUtils.remove_entry_secure(dir) crashes when a dir is under
      # a world-writable directory because it tries to open directory.
      # Opening directory is not allowed in Java.
      tmp = nil
      for dir in [ENV['TMPDIR'], ENV['TMP'], ENV['TEMP'], @@systmpdir, '/tmp', '.']
        puts "Next dir: #{dir}"
        next if !dir
        dir = File.expand_path(dir)
        puts "Expanded dir: #{dir}"
        stat = File.stat(dir)
        puts "stat = #{stat}"
        puts "stat.directory? = #{stat.directory?}"
        puts "stat.writable? = #{stat.writable?}"
        #puts "stat.sticky? = #{stat.sticky?}"
        puts "stat.world_writable? = #{stat.world_writable?}"
        puts "------------------------------------------------------------"
        if stat = File.stat(dir) and stat.directory? and stat.writable? and
            (!(@@using_19 && stat.world_writable?) )#|| stat.sticky?)
          tmp = dir
          break
        end
      end

      unless tmp
        raise ArgumentError, "Unable to find a non world-writable directory for Dir::tmpdir. Consider setting ENV['TMPDIR'], ENV['TMP'] or ENV['TEMP'] to a non world-writable directory."
      end

      tmp
    end
  end

This is the output I see on the console when I try to send a large payload to the http input:

Pipeline main started {:file=>"/admin/logstash/logstash-2.3.2/vendor/bundle/jruby/1.9/gems/logstash-core-2.3.2-java/lib/logstash/agent.rb", :line=>"465", :method=>"start_pipeline"}
Next dir:
Next dir: C:\Users\bvidovic\AppData\Local\Temp
Expanded dir: C:/Users/bvidovic/AppData/Local/Temp
stat = #<File::Stat:0x2712161>
stat.directory? = true
stat.writable? = false
stat.world_writable? =
------------------------------------------------------------
Next dir: C:\Users\bvidovic\AppData\Local\Temp
Expanded dir: C:/Users/bvidovic/AppData/Local/Temp
stat = #<File::Stat:0x51466887>
stat.directory? = true
stat.writable? = false
stat.world_writable? =
------------------------------------------------------------
Next dir: C:\Users\bvidovic\AppData\Local\Temp\
Expanded dir: C:/Users/bvidovic/AppData/Local/Temp
stat = #<File::Stat:0x6578a0c0>
stat.directory? = true
stat.writable? = false
stat.world_writable? =
------------------------------------------------------------
Next dir: /tmp
Expanded dir: C:/tmp
stat = #<File::Stat:0x5281d14b>
stat.directory? = true
stat.writable? = false
stat.world_writable? =
------------------------------------------------------------
Next dir: .
Expanded dir: C:/Users/bvidovic
stat = #<File::Stat:0x48d3bd3e>
stat.directory? = true
stat.writable? = false
stat.world_writable? =
------------------------------------------------------------

There are two problems i've found:

1. stat.writable? is always false for every dir it tries (even if i run logstash as administrator). I'm not sure why, the directories exist and have nothing special about them.
2. Notice that I commented out the stat.sticky? check because when this is called, ruby/logstash hangs indefinitely and never returns a value (I waited up to 5 minutes before killing the process).

Also if I hard-code the function to simply return the dir (with no other checks), then the HTTP input works for large payloads:

  tmp = File.expand_path("C:/Users/bvidovic/AppData/Local/Temp/")
  return tmp

[jsvd]

@bradvido I believe this is due to jruby/jruby#3505, a jruby 1.7.23 bug stat makes writable? incorrectly return false in windows.
In the past we released logstash with jruby 1.7.24 partially because of this, but unfortunately .24 introduced a race condition issue in regular expressions, so we had to revert back to .23 which was the lesser of two evils.

For the next releases we're considering .25 which seems to fix both issues, but we need a bit of time to understand if nothing else fails.

[bradvido]

Thanks @jsvd
For now, I've removed the "write large request to a temporary file" behavior of the the http input, and all things are good. I just have to make sure my payloads aren't so excessive that they will cause problems being stored in memory.

I'll wait for the next release for a proper fix.