search

p0pr0ck5 / lua-resty-waf

High-performance WAF built on the OpenResty stack
GNU General Public License v3.0
1.28k stars 305 forks source link

403 Forbidden error in OpenResty Nginx with lua-resty-waf #279

Closed junoteam closed 7 years ago

junoteam commented 7 years ago

Hi,

in some reason, request URL that looks like: https://jenkins-auto.xxx.com/$stapler/bound/fbad42ef-bd77-4484-a394-775277720e7e/render

get: Status Code: 403 Forbidden lua-resty-waf has next configuration for debugging: 

  access_by_lua_block {
    local lrw = require "resty.waf"
    local waf = lrw:new()
    waf:set_option("debug", true)
    waf:set_option("mode", "ACTIVE")
    waf:set_option("event_log_ssl", true)
    waf:set_option("event_log_target", "file")
    waf:set_option("event_log_target_path", "/var/log/openresty/waf.log")
    waf:set_option("event_log_request_headers", true)
    waf:set_option("event_log_request_arguments", true)
    waf:set_option("event_log_request_body", true)
    waf:set_option("event_log_periodic_flush", 1)
    waf:set_option("ignore_ruleset", "41000_sqli")
    waf:exec()
  }

In log of WAF I see nothing. In log of OpenResty Nginx I see this: 

70.39.157.193 - - [24/May/2017:14:33:21 +0000] "GET /$stapler/bound/36b9b4f5-2a58-474c-826c-b9a5aa7dcde8/render HTTP/1.1" 404 342 "-" "Mozilla/5.0 (compatible; MSIE 9.0; Windows NT 6.1; WOW64; Trident/5.0)" "-"

This block prevents from working drop-down menu in Jenkins UI.

junoteam commented 7 years ago

This is what I see in error log of Nginx in debug mode: 

2017/05/24 15:14:18 [debug] 15682#0: *122662 http write filter 0000000000000000
2017/05/24 15:14:18 [debug] 15682#0: *122662 http copy filter: 0 "/$stapler/bound/031daa44-826c-415d-9668-406df8611a10/render?"
2017/05/24 15:14:18 [debug] 15682#0: *122662 http finalize request: 0, "/$stapler/bound/031daa44-826c-415d-9668-406df8611a10/render?" a:1, c:1
2017/05/24 15:14:18 [debug] 15682#0: *122662 set http keepalive handler
2017/05/24 15:14:18 [debug] 15682#0: *122662 http close request
2017/05/24 15:14:18 [debug] 15682#0: *122662 lua log handler, uri:"/$stapler/bound/031daa44-826c-415d-9668-406df8611a10/render" c:1
2017/05/24 15:14:18 [debug] 15682#0: *122662 [lua] waf.lua:805: write_log_events(): Not attempting to write log as lua-resty-waf was never exec'd
2017/05/24 15:14:18 [debug] 15682#0: *122662 http log handler
2017/05/24 15:14:18 [debug] 15682#0: *122662 run cleanup: 0000000001AE79C0
junoteam commented 7 years ago

Also I see this strings: 

2017/05/24 15:15:45 [debug] 15683#0: *122909 lua exit with code 403
2017/05/24 15:15:45 [debug] 15683#0: *122909 lua resume returned 1
2017/05/24 15:15:45 [debug] 15683#0: *122909 lua thread yielded
2017/05/24 15:15:45 [debug] 15683#0: *122909 lua thread aborting request with status 403
2017/05/24 15:15:45 [debug] 15683#0: *122909 lua request cleanup: forcible=0
2017/05/24 15:15:45 [debug] 15683#0: *122909 http finalize request: 403, "/$stapler/bound/031daa44-826c-415d-9668-406df8611a10/render?" a:1, c:1
2017/05/24 15:15:45 [debug] 15683#0: *122909 http special response: 403, "/$stapler/bound/031daa44-826c-415d-9668-406df8611a10/render?"
2017/05/24 15:15:45 [debug] 15683#0: *122909 http set discard body
2017/05/24 15:15:45 [debug] 15683#0: *122909 lua capture header filter, uri "/$stapler/bound/031daa44-826c-415d-9668-406df8611a10/render"
2017/05/24 15:15:45 [debug] 15683#0: *122909 HTTP/1.1 403 Forbidden
junoteam commented 7 years ago

And this is full log: 

2017/05/24 15:22:22 [debug] 15682#0: *123143 http process request line
2017/05/24 15:22:22 [debug] 15682#0: *123143 http request line: "POST /$stapler/bound/031daa44-826c-415d-9668-406df8611a10/render HTTP/1.1"
2017/05/24 15:22:22 [debug] 15682#0: *123143 http uri: "/$stapler/bound/031daa44-826c-415d-9668-406df8611a10/render"
2017/05/24 15:22:22 [debug] 15682#0: *123143 http args: ""
2017/05/24 15:22:22 [debug] 15682#0: *123143 http exten: ""
2017/05/24 15:22:22 [debug] 15682#0: *123143 http process request header line
2017/05/24 15:22:22 [debug] 15682#0: *123143 http header: "Host: jenkins-auto.xxx.com"
2017/05/24 15:22:22 [debug] 15682#0: *123143 http header: "Connection: keep-alive"
2017/05/24 15:22:22 [debug] 15682#0: *123143 http header: "Content-Length: 2"
2017/05/24 15:22:22 [debug] 15682#0: *123143 http header: "Origin: https://jenkins-auto.xxx.com"
2017/05/24 15:22:22 [debug] 15682#0: *123143 http header: "User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_11_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/58.0.3029.110 Safari/537.36"
2017/05/24 15:22:22 [debug] 15682#0: *123143 http header: "Content-type: application/x-stapler-method-invocation;charset=UTF-8"
2017/05/24 15:22:22 [debug] 15682#0: *123143 http header: "Accept: text/javascript, text/html, application/xml, text/xml, */*"
2017/05/24 15:22:22 [debug] 15682#0: *123143 posix_memalign: 0000000001AE77A0:4096 @16
2017/05/24 15:22:22 [debug] 15682#0: *123143 http header: "X-Prototype-Version: 1.7"
2017/05/24 15:22:22 [debug] 15682#0: *123143 http header: "Crumb: 232f0689-de72-4b8f-bb4b-e0643e2ed688"
2017/05/24 15:22:22 [debug] 15682#0: *123143 http header: "X-Requested-With: XMLHttpRequest"
2017/05/24 15:22:22 [debug] 15682#0: *123143 http header: "DNT: 1"
2017/05/24 15:22:22 [debug] 15682#0: *123143 http header: "Referer: https://jenkins-auto.xxx.com/job/my_test/configure"
2017/05/24 15:22:22 [debug] 15682#0: *123143 http header: "Accept-Encoding: gzip, deflate, br"
2017/05/24 15:22:22 [debug] 15682#0: *123143 http header: "Accept-Language: en-US,en;q=0.8"
2017/05/24 15:22:22 [debug] 15682#0: *123143 http alloc large header buffer
2017/05/24 15:22:22 [debug] 15682#0: *123143 posix_memalign: 0000000001AE87B0:512 @16
2017/05/24 15:22:22 [debug] 15682#0: *123143 malloc: 0000000001BC8C80:65536
2017/05/24 15:22:22 [debug] 15682#0: *123143 http large header alloc: 0000000001BC8C80 65536
2017/05/24 15:22:22 [debug] 15682#0: *123143 http large header copy: 319
2017/05/24 15:22:22 [debug] 15682#0: *123143 SSL_read: 15
2017/05/24 15:22:22 [debug] 15682#0: *123143 SSL_read: -1
2017/05/24 15:22:22 [debug] 15682#0: *123143 SSL_get_error: 2
2017/05/24 15:22:22 [debug] 15682#0: *123143 http header: "Cookie: JSESSIONID.4378fb4e=node0x5q89hub2aky1foe2998fccex8.node0; JSESSIONID.09975291=lov6dfdhvpnc1m6wly8prz90t; JSESSIONID.8574c5f8=zinf5ejcdvua1j37cdyyewt9t; JSESSIONID.280704e0=197dovonke3ebfrzhddvvhp8w; JSESSIONID.302517ae=g8ajb3w5wdif1byxwuf9zmvoa; JSESSIONID.80b6b06f=eoh8nvndmj2s1j9xw03ix5qs2; screenResolution=1920x1080"
2017/05/24 15:22:22 [debug] 15682#0: *123143 http header done
2017/05/24 15:22:22 [debug] 15682#0: *123143 event timer del: 5: 1495639522429
2017/05/24 15:22:22 [debug] 15682#0: *123143 rewrite phase: 0
2017/05/24 15:22:22 [debug] 15682#0: *123143 rewrite phase: 1
2017/05/24 15:22:22 [debug] 15682#0: *123143 test location: "/"
2017/05/24 15:22:22 [debug] 15682#0: *123143 using configuration "/"
2017/05/24 15:22:22 [debug] 15682#0: *123143 http cl:2 max:10485760
2017/05/24 15:22:22 [debug] 15682#0: *123143 rewrite phase: 3
2017/05/24 15:22:22 [debug] 15682#0: *123143 rewrite phase: 4
2017/05/24 15:22:22 [debug] 15682#0: *123143 post rewrite phase: 5
2017/05/24 15:22:22 [debug] 15682#0: *123143 generic phase: 6
2017/05/24 15:22:22 [debug] 15682#0: *123143 generic phase: 7
2017/05/24 15:22:22 [debug] 15682#0: *123143 access phase: 8
2017/05/24 15:22:22 [debug] 15682#0: *123143 access phase: 9
2017/05/24 15:22:22 [debug] 15682#0: *123143 access phase: 10
2017/05/24 15:22:22 [debug] 15682#0: *123143 lua access handler, uri:"/$stapler/bound/031daa44-826c-415d-9668-406df8611a10/render" c:1
2017/05/24 15:22:22 [debug] 15682#0: *123143 lua creating new thread
2017/05/24 15:22:22 [debug] 15682#0: *123143 lua reset ctx
2017/05/24 15:22:22 [debug] 15682#0: *123143 http cleanup add: 0000000001AE79A8
2017/05/24 15:22:22 [debug] 15682#0: *123143 lua run thread, top:0 c:1
2017/05/24 15:22:22 [debug] 15682#0: *123143 add cleanup: 0000000001AE79C0
2017/05/24 15:22:22 [info] 15682#0: *123143 [lua] request.lua:35: parse_request_body(): [856ad9e5ddb68d120ad5] Examining content type application/x-stapler-method-invocation;charset=UTF-8, client: 199.203.151.53, server: jenkins-auto.xxx.com, request: "POST /$stapler/bound/031daa44-826c-415d-9668-406df8611a10/render HTTP/1.1", host: "jenkins-auto.xxx.com", referrer: "https://jenkins-auto.xxx.com/job/my_test/configure"
2017/05/24 15:22:22 [info] 15682#0: *123143 [lua] request.lua:158: parse_request_body(): [856ad9e5ddb68d120ad5] application/x-stapler-method-invocation;charset=UTF-8 not a valid content type!, client: 199.203.151.53, server: jenkins-auto.xxx.com, request: "POST /$stapler/bound/031daa44-826c-415d-9668-406df8611a10/render HTTP/1.1", host: "jenkins-auto.xxx.com", referrer: "https://jenkins-auto.xxx.com/job/my_test/configure"
2017/05/24 15:22:22 [debug] 15682#0: *123143 lua exit with code 403
2017/05/24 15:22:22 [debug] 15682#0: *123143 lua resume returned 1
2017/05/24 15:22:22 [debug] 15682#0: *123143 lua thread yielded
2017/05/24 15:22:22 [debug] 15682#0: *123143 lua thread aborting request with status 403
2017/05/24 15:22:22 [debug] 15682#0: *123143 lua request cleanup: forcible=0
2017/05/24 15:22:22 [debug] 15682#0: *123143 http finalize request: 403, "/$stapler/bound/031daa44-826c-415d-9668-406df8611a10/render?" a:1, c:1
2017/05/24 15:22:22 [debug] 15682#0: *123143 http special response: 403, "/$stapler/bound/031daa44-826c-415d-9668-406df8611a10/render?"
2017/05/24 15:22:22 [debug] 15682#0: *123143 http set discard body
2017/05/24 15:22:22 [debug] 15682#0: *123143 lua capture header filter, uri "/$stapler/bound/031daa44-826c-415d-9668-406df8611a10/render"
2017/05/24 15:22:22 [debug] 15682#0: *123143 HTTP/1.1 403 Forbidden
Server: openresty/1.11.2.3
Date: Wed, 24 May 2017 15:22:22 GMT
Content-Type: text/html
Content-Length: 577
Connection: keep-alive

2017/05/24 15:22:22 [debug] 15682#0: *123143 write new buf t:1 f:0 0000000001AE7A78, pos 0000000001AE7A78, size: 161 file: 0, size: 0
2017/05/24 15:22:22 [debug] 15682#0: *123143 http write filter: l:0 f:0 s:161
2017/05/24 15:22:22 [debug] 15682#0: *123143 http output filter "/$stapler/bound/031daa44-826c-415d-9668-406df8611a10/render?"
2017/05/24 15:22:22 [debug] 15682#0: *123143 http copy filter: "/$stapler/bound/031daa44-826c-415d-9668-406df8611a10/render?"
2017/05/24 15:22:22 [debug] 15682#0: *123143 lua capture body filter, uri "/$stapler/bound/031daa44-826c-415d-9668-406df8611a10/render"
2017/05/24 15:22:22 [debug] 15682#0: *123143 http postpone filter "/$stapler/bound/031daa44-826c-415d-9668-406df8611a10/render?" 0000000001AE7C98
2017/05/24 15:22:22 [debug] 15682#0: *123143 write old buf t:1 f:0 0000000001AE7A78, pos 0000000001AE7A78, size: 161 file: 0, size: 0
2017/05/24 15:22:22 [debug] 15682#0: *123143 write new buf t:0 f:0 0000000000000000, pos 00000000007A42C0, size: 116 file: 0, size: 0
2017/05/24 15:22:22 [debug] 15682#0: *123143 write new buf t:0 f:0 0000000000000000, pos 00000000007A4980, size: 59 file: 0, size: 0
2017/05/24 15:22:22 [debug] 15682#0: *123143 write new buf t:0 f:0 0000000000000000, pos 00000000007A47A0, size: 402 file: 0, size: 0
2017/05/24 15:22:22 [debug] 15682#0: *123143 http write filter: l:1 f:0 s:738
2017/05/24 15:22:22 [debug] 15682#0: *123143 http write filter limit 0
2017/05/24 15:22:22 [debug] 15682#0: *123143 malloc: 0000000001AC26C0:16384
2017/05/24 15:22:22 [debug] 15682#0: *123143 SSL buf copy: 161
2017/05/24 15:22:22 [debug] 15682#0: *123143 SSL buf copy: 116
2017/05/24 15:22:22 [debug] 15682#0: *123143 SSL buf copy: 59
2017/05/24 15:22:22 [debug] 15682#0: *123143 SSL buf copy: 402
2017/05/24 15:22:22 [debug] 15682#0: *123143 SSL to write: 738
2017/05/24 15:22:22 [debug] 15682#0: *123143 SSL_write: 738
2017/05/24 15:22:22 [debug] 15682#0: *123143 http write filter 0000000000000000
2017/05/24 15:22:22 [debug] 15682#0: *123143 http copy filter: 0 "/$stapler/bound/031daa44-826c-415d-9668-406df8611a10/render?"
2017/05/24 15:22:22 [debug] 15682#0: *123143 http finalize request: 0, "/$stapler/bound/031daa44-826c-415d-9668-406df8611a10/render?" a:1, c:1
2017/05/24 15:22:22 [debug] 15682#0: *123143 set http keepalive handler
2017/05/24 15:22:22 [debug] 15682#0: *123143 http close request
2017/05/24 15:22:22 [debug] 15682#0: *123143 lua log handler, uri:"/$stapler/bound/031daa44-826c-415d-9668-406df8611a10/render" c:1
2017/05/24 15:22:22 [debug] 15682#0: *123143 [lua] waf.lua:805: write_log_events(): Not attempting to write log as lua-resty-waf was never exec'd
2017/05/24 15:22:22 [debug] 15682#0: *123143 http log handler
2017/05/24 15:22:22 [debug] 15682#0: *123143 run cleanup: 0000000001AE79C0
2017/05/24 15:22:22 [debug] 15682#0: lua release ngx.ctx at ref 3
2017/05/24 15:22:22 [debug] 15682#0: *123143 free: 0000000001AD2E90, unused: 3
2017/05/24 15:22:22 [debug] 15682#0: *123143 free: 0000000001AE77A0, unused: 2383
2017/05/24 15:22:22 [debug] 15682#0: *123143 free: 0000000001B4F660
2017/05/24 15:22:22 [debug] 15682#0: *123143 hc free: 0000000000000000 0
2017/05/24 15:22:22 [debug] 15682#0: *123143 hc busy: 0000000001AE87D0 1
2017/05/24 15:22:22 [debug] 15682#0: *123143 free: 0000000001BC8C80
2017/05/24 15:22:22 [debug] 15682#0: *123143 free: 0000000001AC26C0
2017/05/24 15:22:22 [debug] 15682#0: *123143 tcp_nodelay
2017/05/24 15:22:22 [debug] 15682#0: *123143 reusable connection: 1
2017/05/24 15:22:22 [debug] 15682#0: *123143 event timer add: 5: 65000:1495639407850
2017/05/24 15:22:22 [debug] 15682#0: worker cycle
2017/05/24 15:22:22 [debug] 15682#0: accept mutex locked
2017/05/24 15:22:22 [debug] 15682#0: epoll timer: 65000
2017/05/24 15:22:23 [debug] 15683#0: timer delta: 500
2017/05/24 15:22:23 [debug] 15683#0: worker cycle
2017/05/24 15:22:23 [debug] 15683#0: accept mutex lock failed: 0
2017/05/24 15:22:23 [debug] 15683#0: epoll timer: 500
2017/05/24 15:22:23 [debug] 15683#0: timer delta: 501
2017/05/24 15:22:23 [debug] 15683#0: worker cycle
2017/05/24 15:22:23 [debug] 15683#0: accept mutex lock failed: 0
2017/05/24 15:22:23 [debug] 15683#0: epoll timer: 500
2017/05/24 15:22:24 [debug] 15683#0: timer delta: 500
2017/05/24 15:22:24 [debug] 15683#0: worker cycle
2017/05/24 15:22:24 [debug] 15683#0: accept mutex lock failed: 0
2017/05/24 15:22:24 [debug] 15683#0: epoll timer: 500
p0pr0ck5 commented 7 years ago

Hey @junoteam,

Here is the relevant entry in the debug log:

2017/05/24 15:22:22 [info] 15682#0: *123143 [lua] request.lua:158: parse_request_body(): [856ad9e5ddb68d120ad5] application/x-stapler-method-invocation;charset=UTF-8 not a valid content type!, client: 199.203.151.53, server: jenkins-auto.xxx.com, request: "POST /$stapler/bound/031daa44-826c-415d-9668-406df8611a10/render HTTP/1.1", host: "jenkins-auto.xxx.com", referrer: "https://jenkins-auto.xxx.com/job/my_test/configure"

See issue #232, this is a known improvement point. With v0.12 we will deprecate (and eventually remove) this native concept of allowed content types, since we will rely on the CRSv3 ruleset to handle this for us. In the interim, you can set the allow_unknown_content_types option (https://github.com/p0pr0ck5/lua-resty-waf#allow_unknown_content_types), or add your known valid content types via allow_content_types (https://github.com/p0pr0ck5/lua-resty-waf#allowed_content_types).

junoteam commented 7 years ago

Hello @p0pr0ck5

I added option allow_unknown_content_types to WAF settings and now it works well! Can't wait for new versions of lua_resty_waf.

Thank you for help and great work!