processing a request without body

Sat Jan 13 07:14:43 UTC 2024

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