processing a request without body

[Muhammad Nuzaihan]

Hi Maxim,

I've verified that even with "curl -X POST
http://localhost/proxy/profile/alice/comment" works. as below debug
logs.

2024/01/13 15:19:44 [debug] 2452969#0: *20 rewrite phase: 0
2024/01/13 15:19:44 [debug] 2452969#0: *20 test location: "/"
2024/01/13 15:19:44 [debug] 2452969#0: *20 test location: "proxy/health"
2024/01/13 15:19:44 [debug] 2452969#0: *20 test location: "proxy/unhealthy"
2024/01/13 15:19:44 [debug] 2452969#0: *20 test location:
"proxy/profile/alice/comment"
2024/01/13 15:19:44 [debug] 2452969#0: *20 using configuration
"/proxy/profile/alice/comment"
2024/01/13 15:19:44 [debug] 2452969#0: *20 http cl:-1 max:1048576
2024/01/13 15:19:44 [debug] 2452969#0: *20 rewrite phase: 2
2024/01/13 15:19:44 [debug] 2452969#0: *20 post rewrite phase: 3
2024/01/13 15:19:44 [debug] 2452969#0: *20 generic phase: 4
2024/01/13 15:19:44 [debug] 2452969#0: *20 malloc: 000055ADC47961F0:16634
2024/01/13 15:19:44 Hello from Go's ValidateRequestBody!
2024/01/13 15:19:44 RequestValidation is running...
2024/01/13 15:19:44 Request body length: 0
2024/01/13 15:19:44 Request body in Go:
2024/01/13 15:19:44 Middleware altered response body, original: , new:
{"code":400,"title":"something's wrong with your request
body","detail":"the request's body did not match your appspec: request
body has an error: value is required but missing"}
2024/01/13 15:19:44 [debug] 2452969#0: *20 http output filter
"/proxy/profile/alice/comment?"
2024/01/13 15:19:44 [debug] 2452969#0: *20 http copy filter:
"/proxy/profile/alice/comment?"
2024/01/13 15:19:44 [debug] 2452969#0: *20 {
  "version":"1.0.0-alpha",
  "dateCreated":1705130384398,
  "executionTime":123456789,
  "request":{
    "ip":"127.0.0.1",
    "httpProtocol":"HTTP\/1.1",
    "uri":"http:\/\/localhost\/proxy\/profile\/alice\/comment",
    "resource":"\/proxy\/profile\/alice\/comment",
    "method":"POST",
    "body":"",
    "headers":{
      "Host":[
        "localhost"
      ],
      "User-Agent":[
        "curl\/7.81.0"
      ],
      "Accept":[
        "*\/*"
      ]
    }
  },
  "response":{
    "statusCode":400,
    "body":"{\"code\":400,\"title\":\"something's wrong with your
request body\",\"detail\":\"the request's body did not match your
appspec: request body has an error: value is required but missing\"}",
    "headers":{}
  }
}
2024/01/13 15:19:44 [debug] 2452969#0: *20 Buffer is successful
2024/01/13 15:19:44 [debug] 2452969#0: *20 Start of firetail send
2024/01/13 15:19:44 [debug] 2452969#0: *20 Sending next RESPONSE body
2024/01/13 15:19:44 [debug] 2452969#0: *20 Sending next REQUEST body
2024/01/13 15:19:44 [debug] 2452969#0: *20 Buffer is successful
2024/01/13 15:19:44 [debug] 2452969#0: *20 INCOMING Request Body: , json {}
2024/01/13 15:19:44 [debug] 2452969#0: *20 Sending next REQUEST body
2024/01/13 15:19:44 [alert] 2452969#0: *20 duplicate last buf in save
filter, client: 127.0.0.1, server: localhost, request: "POST
/proxy/profile/alice/comment HTTP/1.1", host: "localhost"
2024/01/13 15:19:44 [notice] 2452668#0: signal 17 (SIGCHLD) received
from 2452969
2024/01/13 15:19:44 [alert] 2452668#0: worker process 2452969 exited
on signal 11 (core dumped)
2024/01/13 15:19:44 [debug] 2452668#0: shmtx forced unlock
2024/01/13 15:19:44 [debug] 2452668#0: wake up, sigio 0
2024/01/13 15:19:44 [debug] 2452668#0: reap children
2024/01/13 15:19:44 [debug] 2452668#0: child: 0 2452969 e:0 t:1 d:0 r:1 j:0
2024/01/13 15:19:44 [debug] 2452668#0: channel 3:7
2024/01/13 15:19:44 [notice] 2452668#0: start worker process 2516641
2024/01/13 15:19:44 [debug] 2452668#0: sigsuspend
2024/01/13 15:19:44 [debug] 2516641#0: add cleanup: 000055ADC472CEC8
2024/01/13 15:19:44 [debug] 2516641#0: malloc: 000055ADC46D9520:8
2024/01/13 15:19:44 [debug] 2516641#0: notify eventfd: 9
2024/01/13 15:19:44 [debug] 2516641#0: testing the EPOLLRDHUP flag: success
2024/01/13 15:19:44 [debug] 2516641#0: malloc: 000055ADC47073D0:6144
2024/01/13 15:19:44 [debug] 2516641#0: malloc: 00007F4DF059E010:253952
2024/01/13 15:19:44 [debug] 2516641#0: malloc: 000055ADC4730510:98304
2024/01/13 15:19:44 [debug] 2516641#0: malloc: 000055ADC4748520:98304
2024/01/13 15:19:44 [debug] 2516641#0: epoll add event: fd:6 op:1 ev:00002001


only with an empty payload like this:

curl -X POST http://localhost/proxy/profile/alice/comment -d '' -H
'Content-Type: application/json'

it doesn't execute.

On Sat, Jan 13, 2024 at 3:14 PM Muhammad Nuzaihan <zaihan at unrealasia.net> wrote:
>
> Hi Maxim, (added some info about URL)
>
> I did enable debug logs before i posted the question.
>
> With json payload, my code is executed right after doing malloc and
> "http request body content length filter".
>
> Without a json payload, it doesn't execute my request
> validation.That's why i thought it might be due to content length is
> 0.
>
> Here is the debug log when i curl with an empty payload:
>
> curl -X POST http://localhost/proxy/profile/alice/comment -d '' -H
> 'Content-Type: application/json'
>
> 2024/01/13 15:01:19 [debug] 2452969#0: *11 rewrite phase: 0
> 2024/01/13 15:01:19 [debug] 2452969#0: *11 test location: "/"
> 2024/01/13 15:01:19 [debug] 2452969#0: *11 test location: "proxy/health"
> 2024/01/13 15:01:19 [debug] 2452969#0: *11 test location: "proxy/unhealthy"
> 2024/01/13 15:01:19 [debug] 2452969#0: *11 test location:
> "proxy/profile/alice/comment"
> 2024/01/13 15:01:19 [debug] 2452969#0: *11 using configuration
> "/proxy/profile/alice/comment"
> 2024/01/13 15:01:19 [debug] 2452969#0: *11 http cl:0 max:1048576
> 2024/01/13 15:01:19 [debug] 2452969#0: *11 rewrite phase: 2
> 2024/01/13 15:01:19 [debug] 2452969#0: *11 post rewrite phase: 3
> 2024/01/13 15:01:19 [debug] 2452969#0: *11 generic phase: 4
> 2024/01/13 15:01:19 [debug] 2452969#0: *11 http request body content
> length filter
> 2024/01/13 15:01:19 [debug] 2452969#0: *11 http read client request body
> 2024/01/13 15:01:19 [debug] 2452969#0: *11 recv: eof:0, avail:0
> 2024/01/13 15:01:19 [debug] 2452969#0: *11 http client request body recv -2
> 2024/01/13 15:01:19 [debug] 2452969#0: *11 http client request body rest 1
> 2024/01/13 15:01:19 [debug] 2452969#0: *11 event timer add: 3: 60000:183385517
> 2024/01/13 15:01:19 [debug] 2452969#0: *11 http finalize request: -4,
> "/proxy/profile/alice/comment?" a:1, c:2
> 2024/01/13 15:01:19 [debug] 2452969#0: *11 http request count:2 blk:0
> 2024/01/13 15:01:19 [debug] 2452969#0: *11 access phase: 7
> 2024/01/13 15:01:19 [debug] 2452969#0: *11 access phase: 8
> 2024/01/13 15:01:19 [debug] 2452969#0: *11 post access phase: 9
> 2024/01/13 15:01:19 [debug] 2452969#0: *11 generic phase: 10
> 2024/01/13 15:01:19 [debug] 2452969#0: *11 generic phase: 11
> 2024/01/13 15:01:19 [debug] 2452969#0: *11 http init upstream, client timer: 1
> 2024/01/13 15:01:19 [debug] 2452969#0: *11 event timer del: 3: 183385517
> 2024/01/13 15:01:19 [debug] 2452969#0: *11 epoll add event: fd:3 op:3
> ev:80002005
>
> Here is the expected debug logs when i curl with a json payload: `curl
> -X POST http://localhost/proxy/profile/alice/comment -d
> '{"comment":"test"}' -H 'Content-Type: application/json'`
>
> 2024/01/13 15:05:59 [debug] 2452969#0: *17 rewrite phase: 0
> 2024/01/13 15:05:59 [debug] 2452969#0: *17 test location: "/"
> 2024/01/13 15:05:59 [debug] 2452969#0: *17 test location: "proxy/health"
> 2024/01/13 15:05:59 [debug] 2452969#0: *17 test location: "proxy/unhealthy"
> 2024/01/13 15:05:59 [debug] 2452969#0: *17 test location:
> "proxy/profile/alice/comment"
> 2024/01/13 15:05:59 [debug] 2452969#0: *17 using configuration
> "/proxy/profile/alice/comment"
> 2024/01/13 15:05:59 [debug] 2452969#0: *17 http cl:18 max:1048576
> 2024/01/13 15:05:59 [debug] 2452969#0: *17 rewrite phase: 2
> 2024/01/13 15:05:59 [debug] 2452969#0: *17 post rewrite phase: 3
> 2024/01/13 15:05:59 [debug] 2452969#0: *17 generic phase: 4
> 2024/01/13 15:05:59 [debug] 2452969#0: *17 http client request body preread 18
> 2024/01/13 15:05:59 [debug] 2452969#0: *17 http request body content
> length filter
> 2024/01/13 15:05:59 [debug] 2452969#0: *17 malloc: 000055ADC47961F0:16634
> 2024/01/13 15:05:59 Hello from Go's ValidateRequestBody!
> 2024/01/13 15:05:59 RequestValidation is running...
> 2024/01/13 15:05:59 Request body length: 18
> 2024/01/13 15:05:59 Request body in Go: {"comment":"test"}
> 2024/01/13 15:05:59 [debug] 2452969#0: *17 http body new buf t:0 f:0
> 0000000000000000, pos 000055ADC478F300, size: 0 file: 0, size: 0
> 2024/01/13 15:05:59 [debug] 2452969#0: *17 malloc: 000055ADC479A300:16634
> 2024/01/13 15:05:59 Hello from Go's ValidateRequestBody!
> 2024/01/13 15:05:59 RequestValidation is running...
> 2024/01/13 15:05:59 Request body length: 18
> 2024/01/13 15:05:59 Request body in Go: {"comment":"test"}
> 2024/01/13 15:05:59 [debug] 2452969#0: *17 http body new buf t:0 f:0
> 0000000000000000, pos 000055ADC478F780, size: 0 file: 0, size: 0
> 2024/01/13 15:05:59 [alert] 2452969#0: *17 duplicate last buf in save
> filter, client: 127.0.0.1, server: localhost, request: "POST
> /proxy/profile/alice/comment HTTP/1.1", host: "localhost"
> 2024/01/13 15:05:59 [debug] 2452969#0: *17 free: 000055ADC479A300
> 2024/01/13 15:05:59 [debug] 2452969#0: *17 http finalize request: -4,
> "/proxy/profile/alice/comment?" a:1, c:2
> 2024/01/13 15:05:59 [debug] 2452969#0: *17 http request count:2 blk:0
> 2024/01/13 15:05:59 [debug] 2452969#0: *17 access phase: 7
> 2024/01/13 15:05:59 [debug] 2452969#0: *17 access phase: 8
> 2024/01/13 15:05:59 [debug] 2452969#0: *17 post access phase: 9
> 2024/01/13 15:05:59 [debug] 2452969#0: *17 generic phase: 10
> 2024/01/13 15:05:59 [debug] 2452969#0: *17 generic phase: 11
> 2024/01/13 15:05:59 [debug] 2452969#0: *17 http init upstream, client timer: 0
> 2024/01/13 15:05:59 [debug] 2452969#0: *17 epoll add event: fd:3 op:3
> ev:80002005
>
> On Sat, Jan 13, 2024 at 3:11 PM Muhammad Nuzaihan <zaihan at unrealasia.net> wrote:
> >
> > Hi Maxim,
> >
> > I did enable debug logs before i posted the question.
> >
> > With json payload, my code is executed right after doing malloc and
> > "http request body content length filter".
> >
> > Without a json payload, it doesn't execute my request
> > validation.That's why i thought it might be due to content length is
> > 0.
> >
> > Here is the debug log when i curl with an empty payload:
> >
> > 2024/01/13 15:01:19 [debug] 2452969#0: *11 rewrite phase: 0
> > 2024/01/13 15:01:19 [debug] 2452969#0: *11 test location: "/"
> > 2024/01/13 15:01:19 [debug] 2452969#0: *11 test location: "proxy/health"
> > 2024/01/13 15:01:19 [debug] 2452969#0: *11 test location: "proxy/unhealthy"
> > 2024/01/13 15:01:19 [debug] 2452969#0: *11 test location:
> > "proxy/profile/alice/comment"
> > 2024/01/13 15:01:19 [debug] 2452969#0: *11 using configuration
> > "/proxy/profile/alice/comment"
> > 2024/01/13 15:01:19 [debug] 2452969#0: *11 http cl:0 max:1048576
> > 2024/01/13 15:01:19 [debug] 2452969#0: *11 rewrite phase: 2
> > 2024/01/13 15:01:19 [debug] 2452969#0: *11 post rewrite phase: 3
> > 2024/01/13 15:01:19 [debug] 2452969#0: *11 generic phase: 4
> > 2024/01/13 15:01:19 [debug] 2452969#0: *11 http request body content
> > length filter
> > 2024/01/13 15:01:19 [debug] 2452969#0: *11 http read client request body
> > 2024/01/13 15:01:19 [debug] 2452969#0: *11 recv: eof:0, avail:0
> > 2024/01/13 15:01:19 [debug] 2452969#0: *11 http client request body recv -2
> > 2024/01/13 15:01:19 [debug] 2452969#0: *11 http client request body rest 1
> > 2024/01/13 15:01:19 [debug] 2452969#0: *11 event timer add: 3: 60000:183385517
> > 2024/01/13 15:01:19 [debug] 2452969#0: *11 http finalize request: -4,
> > "/proxy/profile/alice/comment?" a:1, c:2
> > 2024/01/13 15:01:19 [debug] 2452969#0: *11 http request count:2 blk:0
> > 2024/01/13 15:01:19 [debug] 2452969#0: *11 access phase: 7
> > 2024/01/13 15:01:19 [debug] 2452969#0: *11 access phase: 8
> > 2024/01/13 15:01:19 [debug] 2452969#0: *11 post access phase: 9
> > 2024/01/13 15:01:19 [debug] 2452969#0: *11 generic phase: 10
> > 2024/01/13 15:01:19 [debug] 2452969#0: *11 generic phase: 11
> > 2024/01/13 15:01:19 [debug] 2452969#0: *11 http init upstream, client timer: 1
> > 2024/01/13 15:01:19 [debug] 2452969#0: *11 event timer del: 3: 183385517
> > 2024/01/13 15:01:19 [debug] 2452969#0: *11 epoll add event: fd:3 op:3
> > ev:80002005
> >
> > Here is the expected debug logs when i curl with a json payload: `curl
> > -X POST http://localhost/proxy/profile/alice/comment -d
> > '{"comment":"test"}' -H 'Content-Type: application/json'`
> >
> > 2024/01/13 15:05:59 [debug] 2452969#0: *17 rewrite phase: 0
> > 2024/01/13 15:05:59 [debug] 2452969#0: *17 test location: "/"
> > 2024/01/13 15:05:59 [debug] 2452969#0: *17 test location: "proxy/health"
> > 2024/01/13 15:05:59 [debug] 2452969#0: *17 test location: "proxy/unhealthy"
> > 2024/01/13 15:05:59 [debug] 2452969#0: *17 test location:
> > "proxy/profile/alice/comment"
> > 2024/01/13 15:05:59 [debug] 2452969#0: *17 using configuration
> > "/proxy/profile/alice/comment"
> > 2024/01/13 15:05:59 [debug] 2452969#0: *17 http cl:18 max:1048576
> > 2024/01/13 15:05:59 [debug] 2452969#0: *17 rewrite phase: 2
> > 2024/01/13 15:05:59 [debug] 2452969#0: *17 post rewrite phase: 3
> > 2024/01/13 15:05:59 [debug] 2452969#0: *17 generic phase: 4
> > 2024/01/13 15:05:59 [debug] 2452969#0: *17 http client request body preread 18
> > 2024/01/13 15:05:59 [debug] 2452969#0: *17 http request body content
> > length filter
> > 2024/01/13 15:05:59 [debug] 2452969#0: *17 malloc: 000055ADC47961F0:16634
> > 2024/01/13 15:05:59 Hello from Go's ValidateRequestBody!
> > 2024/01/13 15:05:59 RequestValidation is running...
> > 2024/01/13 15:05:59 Request body length: 18
> > 2024/01/13 15:05:59 Request body in Go: {"comment":"test"}
> > 2024/01/13 15:05:59 [debug] 2452969#0: *17 http body new buf t:0 f:0
> > 0000000000000000, pos 000055ADC478F300, size: 0 file: 0, size: 0
> > 2024/01/13 15:05:59 [debug] 2452969#0: *17 malloc: 000055ADC479A300:16634
> > 2024/01/13 15:05:59 Hello from Go's ValidateRequestBody!
> > 2024/01/13 15:05:59 RequestValidation is running...
> > 2024/01/13 15:05:59 Request body length: 18
> > 2024/01/13 15:05:59 Request body in Go: {"comment":"test"}
> > 2024/01/13 15:05:59 [debug] 2452969#0: *17 http body new buf t:0 f:0
> > 0000000000000000, pos 000055ADC478F780, size: 0 file: 0, size: 0
> > 2024/01/13 15:05:59 [alert] 2452969#0: *17 duplicate last buf in save
> > filter, client: 127.0.0.1, server: localhost, request: "POST
> > /proxy/profile/alice/comment HTTP/1.1", host: "localhost"
> > 2024/01/13 15:05:59 [debug] 2452969#0: *17 free: 000055ADC479A300
> > 2024/01/13 15:05:59 [debug] 2452969#0: *17 http finalize request: -4,
> > "/proxy/profile/alice/comment?" a:1, c:2
> > 2024/01/13 15:05:59 [debug] 2452969#0: *17 http request count:2 blk:0
> > 2024/01/13 15:05:59 [debug] 2452969#0: *17 access phase: 7
> > 2024/01/13 15:05:59 [debug] 2452969#0: *17 access phase: 8
> > 2024/01/13 15:05:59 [debug] 2452969#0: *17 post access phase: 9
> > 2024/01/13 15:05:59 [debug] 2452969#0: *17 generic phase: 10
> > 2024/01/13 15:05:59 [debug] 2452969#0: *17 generic phase: 11
> > 2024/01/13 15:05:59 [debug] 2452969#0: *17 http init upstream, client timer: 0
> > 2024/01/13 15:05:59 [debug] 2452969#0: *17 epoll add event: fd:3 op:3
> > ev:80002005
> >
> > Thank you Maxim for answering my questions!
> >
> > On Sat, Jan 13, 2024 at 6:23 AM Maxim Dounin <mdounin at mdounin.ru> wrote:
> > >
> > > Hello!
> > >
> > > On Fri, Jan 12, 2024 at 10:17:42PM +0800, Muhammad Nuzaihan wrote:
> > >
> > > > Hi Maxim,
> > > >
> > > > Thank you so much for your explaination.
> > > >
> > > > I have another question. If i have an empty string in my payload, it
> > > > skips the phase handler completely.
> > > >
> > > > Example: curl -X POST http://localhost/proxy/profile/alice/comment -d
> > > > '' -H 'Content-Type: application/json'
> > > >
> > > > the flag "-d ''"
> > > >
> > > > I do doing it at NGX_HTTP_ACCESS_PHASE in the handler. It seems that
> > > > if "content_length = 0", it skips the access phase handler as well?
> > >
> > > Access phase handlers are called for all requests (unless these
> > > are rejected at earlier stages).  If in doubt, consider configuring
> > > debug logging and add appropriate debug logging to your module, it
> > > should make things obvious enough.
> > >
> > > --
> > > Maxim Dounin
> > > http://mdounin.ru/
> > > _______________________________________________
> > > nginx-devel mailing list
> > > nginx-devel at nginx.org
> > > https://mailman.nginx.org/mailman/listinfo/nginx-devel