Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Requests from Lambda logging "POST body is: null" #15

Closed
geerlingguy opened this Issue Aug 19, 2017 · 7 comments

Comments

Projects
None yet
1 participant
@geerlingguy
Copy link
Owner

commented Aug 19, 2017

I am trying to get this running on a fresh new server, but both trying with a Docker-based Drupal VM container, and with a native LAMP stack, I am not able to get any $body data in the put() or post() REST endpoint for Rekognition API.

I've tested the original site inside of AWS, and it's getting the request body/chunked data. And I also set up a test script (test.php):

<?php

/**
 * @file
 * Test functionality to log PHP request input (e.g. POST or PUT request bodies)
 * to syslog. Tail syslog with `sudo tail -f /var/log/syslog` to see.
 */

syslog(LOG_DEBUG, "Incoming test PHP request...");
$input = file_get_contents('php://input');
syslog(LOG_DEBUG, print_r($input, TRUE));
syslog(LOG_DEBUG, "Test PHP request complete...");

To log incoming requests. On the servers I'm trying to build with PHP 7.1.x for this project, $input is always empty:

    Aug 19 20:05:33 gallery ool www: Incoming test PHP request...
    Aug 19 20:05:33 gallery ool www:
    Aug 19 20:05:33 gallery ool www: Test PHP request complete...

But if I have the same script running on a similar server elsewhere (one that I know has not had any weird issues in the past, and is running PHP 7.0.x), it is populated:

    Aug 19 16:04:41 www ool www: Incoming test PHP request...
    Aug 19 16:04:41 www ool www: {"Bucket":"test-bucket","Name":"Test Object"}
    Aug 19 16:04:41 www ool www: Test PHP request complete...

Here's the AWS Lambda function I'm invoking to test:

// Lambda function (for the nodejs6.10 runtime) which does the following:
//
//   - Sends a POST request to the hostname and endpoint as configured.
//
// Curl equivalent:
//   curl -H "Content-Type: application/json" -X POST -d '{"Bucket":"test-bucket","Name":"Test Object"}' http://gallery.jeffgeerling.com/test.php

'use strict';

const http = require('http');
const https = require('https');

exports.handler = (event, context, callback) => {
    var body='';

    var options_post = {
        host: "gallery.jeffgeerling.com",
        path: "/test.php",
        method: "POST",
        headers: {
            "Content-Type": "application/json"
        }
    };

    var reqPost = http.request(options_post, function(res) {
        console.log("POST request statusCode: ", res.statusCode);
        res.on('data', function (chunk) {
            body += chunk;
        });
    });

    var jsonObject = {
        Bucket: 'test-bucket',
        Name: 'Test Object'
    }
    console.log("jsonObject: ", JSON.stringify(jsonObject));

    setTimeout(function() {
      reqPost.write(JSON.stringify(jsonObject));
      reqPost.end();
    }, 4000);

};

And a cURL equivalent:

curl -H "Content-Type: application/json" -X POST -d '{"Bucket":"test-bucket","Name":"Test Object"}' http://gallery.jeffgeerling.com/test.php
@geerlingguy

This comment has been minimized.

Copy link
Owner Author

commented Aug 19, 2017

It gets weirder:

  • I tried switching to PHP 7.0 instead of 7.1 (the php-versions role makes this really easy!), but that made no difference.
  • If I run the cURL command from my home computer, I do get the request body on the DigitalOcean droplet:
Aug 19 20:20:23 gallery ool www: Incoming test PHP request...
Aug 19 20:20:23 gallery ool www: {"Bucket":"test-bucket","Name":"Test Object"}
Aug 19 20:20:23 gallery ool www: Test PHP request complete...

Head-scratcher. Is it possible DigitalOcean has some sort of filtering going on for incoming requests from AWS? Or AWS has outgoing filtering? Or PHP is just trying to drive me insane???

@geerlingguy

This comment has been minimized.

Copy link
Owner Author

commented Aug 19, 2017

It gets stranger yet...

$ sudo ngrep "POST" tcp and port 80
interface: eth0 (165.227.96.0/255.255.240.0)
filter: (ip or ip6) and ( tcp and port 80 )
match: POST
####
T 54.237.220.121:40842 -> 165.227.102.121:80 [AP]
  POST /test.php HTTP/1.1..Content-Type: application/json..Host: gallery.jeffgeerling.com..Connection: close..Tran
  sfer-Encoding: chunked....2d..{"Bucket":"test-bucket","Name":"Test Object"}..                                      
#######

Kudos to this Stack Overflow answer regarding debugging POST requests (or, really, any other kinds of requests).

So I've verified the server itself is receiving the chunked body... what the heck?

Compare the above with what I get from the cURL request:

T 68.119.255.196:64999 -> 165.227.102.121:80 [AP]
  POST /jjgtest.php HTTP/1.1..Host: gallery.jeffgeerling.com..User-Agent: curl/7.54.0..Accept: */*..Content-Type: app
  lication/json..Content-Length: 45....{"Bucket":"test-bucket","Name":"Test Object"}

Maybe it's the chunked encoding?

@geerlingguy

This comment has been minimized.

Copy link
Owner Author

commented Aug 19, 2017

Aha, if I use -H "Transfer-Encoding: chunked", then I can reproduce the problem!

# Works.
curl -H "Content-Type: application/json" -X POST -d '{"Bucket":"test-bu
cket","Name":"Test Object"}' http://gallery.jeffgeerling.com/test.php

# Doesn't work.
curl -H "Content-Type: application/json" -H "Transfer-Encoding: chunked" -X POST -d '{"Bucket":"test-bu
cket","Name":"Test Object"}' http://gallery.jeffgeerling.com/test.php

So, now researching what could cause chunked transfers to result in empty POST bodies in PHP...

@geerlingguy

This comment has been minimized.

Copy link
Owner Author

commented Aug 20, 2017

So... I was thinking "ah, maybe I'll try using fastcgi with PHP-FPM instead of proxy_fcgi. But nope. Now it reports back for chunked:

<title>411 Length Required</title>
</head><body>
<h1>Length Required</h1>
<p>A request of the requested method POST requires a valid Content-length.<br />
</p>
<hr>
<address>Apache/2.4.18 (Ubuntu) Server at gallery.jeffgeerling.com Port 80</address>

So. Looks like I can either change the Lambda function to send a content length (which should work with any of the combinations I've tried), I can switch to Nginx (the other server where I can confirm this is working is using Nginx... and I believe requests are terminated in an Nginx balancer in Acquia hosting, which is the reason this didn't fail there—though I think they're also using mod_php so that probably would work too!), or I can spend another 10+ hours debugging this issue in mod_proxy_fcgi-land.

Honestly, switching to non-chunked transfer may be the best option if I can swing it (in the Lambda function), because then I can just keep the configs all the same otherwise (or still use the Docker container approach if I want).

@geerlingguy

This comment has been minimized.

Copy link
Owner Author

commented Aug 20, 2017

And here's the patch of what I tried for replacing proxy_fcgi with fastcgi (and action):

try-fastcgi-instead-of-proxy-fcgi.patch.txt

@geerlingguy

This comment has been minimized.

Copy link
Owner Author

commented Aug 20, 2017

@geerlingguy

This comment has been minimized.

Copy link
Owner Author

commented Aug 20, 2017

Who'd'a thunk it, using the old stalwart mod_php seems to have fixed this chunked transfer issue... and now, success:

it-works-yay-jeff-geerling-face-detected-rekognized

Sorry if you're offended by the giant mugshot :P

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.