search

FRiCKLE / ngx_cache_purge

nginx module which adds ability to purge content from FastCGI, proxy, SCGI and uWSGI caches.
http://labs.frickle.com/nginx_ngx_cache_purge/
Other
1.06k stars 311 forks source link

nginx 1.0.5 / freebsd 8 - error 500 #3

Closed hasanove closed 13 years ago

hasanove commented 13 years ago

sorry if this is the wrong place, I did not find any other where I can submit this issue

i have just installed ngx_cache_purge and am noticing strange behaviour

if entry is not in the cache, I get 404 error, which I guess is OK if entry is in the cache, I get 500 error and only after few refreshes I get "successfull purge"

i am happy to provide any additional info if this is not the expected result

PiotrSikora commented 13 years ago

I've just tested ngx_cache_purge-1.3 on FreeBSD-8.2 with nginx-1.0.5 and everything works fine for me.

Did you install it from ports or from the source?

Also, could you provide your configuration and see if there is anything in your error log?

hasanove commented 13 years ago

i have installed from the ports by simply enabling this module

my error log level set to "error" and at this level it did not write anything to logs at all. I will try to increase log level to see if something is thrown during the error

am I right in understanding that 500 error is not supposed to be returned, unless there is a problem with the module itself?

hasanove commented 13 years ago

i have changed error log level to debug and still nothing related to this request

PiotrSikora commented 13 years ago

Yes, 500 shouldn't happen. Did you tamper with the on-disk cache or something similar?

And please provide your configuration.

hasanove commented 13 years ago

on-disk cache of your module? i did not know it existed, so no :)

my config is quite large and has a number of includes, so I am not posting what I believe is irrelevant (extra locations, servers, logs etc.). Let me know if you do need full config.

    gzip             on;
    gzip_comp_level     6;
    gzip_types  text/plain text/css application/x-javascript text/javascript;
    gzip_proxied any;

    sendfile       off;

    aio             on;
    output_buffers  1 64k;

    tcp_nopush     on;
    tcp_nodelay    on;

    keepalive_timeout  65;

    proxy_cache_path  /home/nginx/cache levels=1:2 keys_zone=one:10m max_size=200m;
    proxy_temp_path /home/nginx/temp;

        client_max_body_size 16M;

        root   /home/bina/www/public;
        ssi on;

        location ~ /prg(/.*) {
            proxy_cache_purge   one $http_host$1;
        }

        location ~* /site/search {
            include rails-config;
            proxy_pass http://bina;
            proxy_cache             one;
            proxy_cache_key         $http_host$request_uri;
            proxy_cache_valid       5m;
            proxy_cache_use_stale   error timeout invalid_header updating;
        }
hasanove commented 13 years ago

is there anything else I could do to debug this problem?

PiotrSikora commented 13 years ago

Sorry, I've been quite busy with other stuff lately... I'll push more verbose version after the weekend.

hasanove commented 13 years ago

sorry to bug, just wondering if I should expect something or better to move on?

PiotrSikora commented 13 years ago

I'm really sorry about the delay, I had crazy month.

Could you try running git HEAD?

PiotrSikora commented 13 years ago

@hasanove: did you have time to test the changes?

hasanove commented 13 years ago

sorry for delay on my side, I just did not want to use production server for testing purposes, so requested to build appropriate environment. This should be ready tomorrow and I will post my results..

hasanove commented 13 years ago

ok, so here is what I have got

2011/09/22 00:17:41 [error] 87190#0: 147 http file cache purge: ngx_http_file_cache_open() failed, client: 109.239.25.221, server: cu02.turbo.az, request: "GET /purge/site/autos/view/190864 HTTP/1.1", host: "cu02.turbo.az" 2011/09/22 00:18:41 [error] 87196#0: 160 http file cache purge: ngx_http_file_cache_open() failed, client: 109.239.25.221, server: cu02.turbo.az, request: "GET /purge/site/autos/view/190864 HTTP/1.1", host: "cu02.turbo.az" 2011/09/22 00:18:58 [error] 87193#0: *163 http file cache purge: ngx_http_file_cache_open() failed, client: 109.239.25.221, server: cu02.turbo.az, request: "GET /purge/site/autos/view/190864 HTTP/1.1", host: "cu02.turbo.az" 2011/09/22 00:20:18 [crit] 87198#0: unlink() "/home/nginx/cache/d/58/77660da6d46de0269b0a14c3b442858d" failed (2: No such file or directory)

apparently, it tries to delete file that does not exist

i was not able to reproduce "unlink" error again, but your debug message is very consistent

PiotrSikora commented 13 years ago

Could you please provide full debug log (http://nginx.org/en/docs/debugging_log.html) for the purge request?

PiotrSikora commented 13 years ago

Also, could you test if turning "aio" directive on/off makes any difference?

hasanove commented 13 years ago

yep, that was it :-)

first, full debug for the error

2011/09/22 11:12:52 [debug] 17555#0: *1 http keepalive handler
2011/09/22 11:12:52 [debug] 17555#0: *1 malloc: 0000000801242800:1024
2011/09/22 11:12:52 [debug] 17555#0: *1 recv: eof:0, avail:602, err:0
2011/09/22 11:12:52 [debug] 17555#0: *1 recv: fd:3 602 of 1024
2011/09/22 11:12:52 [debug] 17555#0: *1 reusable connection: 0
2011/09/22 11:12:52 [debug] 17555#0: *1 malloc: 0000000801272700:1264
2011/09/22 11:12:52 [debug] 17555#0: *1 event timer del: 3: 1316672026053
2011/09/22 11:12:52 [debug] 17555#0: *1 generic phase: 0
2011/09/22 11:12:52 [debug] 17555#0: *1 rewrite phase: 1
2011/09/22 11:12:52 [debug] 17555#0: *1 test location: "/"
2011/09/22 11:12:52 [debug] 17555#0: *1 test location: ~ "/purge(/.*)"
2011/09/22 11:12:52 [debug] 17555#0: *1 using configuration "/purge(/.*)"
2011/09/22 11:12:52 [debug] 17555#0: *1 http cl:-1 max:1048576
2011/09/22 11:12:52 [debug] 17555#0: *1 rewrite phase: 3
2011/09/22 11:12:52 [debug] 17555#0: *1 post rewrite phase: 4
2011/09/22 11:12:52 [debug] 17555#0: *1 generic phase: 5
2011/09/22 11:12:52 [debug] 17555#0: *1 generic phase: 6
2011/09/22 11:12:52 [debug] 17555#0: *1 generic phase: 7
2011/09/22 11:12:52 [debug] 17555#0: *1 access phase: 8
2011/09/22 11:12:52 [debug] 17555#0: *1 access phase: 9
2011/09/22 11:12:52 [debug] 17555#0: *1 post access phase: 10
2011/09/22 11:12:52 [debug] 17555#0: *1 http set discard body
2011/09/22 11:12:52 [debug] 17555#0: *1 http script var: "cu02.turbo.az"
2011/09/22 11:12:52 [debug] 17555#0: *1 http script capture: "/site/autos/view/189902"
2011/09/22 11:12:52 [debug] 17555#0: *1 http cache key: "cu02.turbo.az/site/autos/view/189902"
2011/09/22 11:12:52 [debug] 17555#0: *1 add cleanup: 00000008012D4C40
2011/09/22 11:12:52 [debug] 17555#0: *1 http file cache exists: 0 e:1
2011/09/22 11:12:52 [debug] 17555#0: *1 cache file: "/home/nginx/cache/0/c6/02ab3c74d93d87556a42990159510c60"
2011/09/22 11:12:52 [debug] 17555#0: *1 add cleanup: 00000008012D4C90
2011/09/22 11:12:52 [debug] 17555#0: *1 http file cache fd: 8
2011/09/22 11:12:52 [debug] 17555#0: *1 aio complete:0 @0:359 /home/nginx/cache/0/c6/02ab3c74d93d87556a42990159510c60
2011/09/22 11:12:52 [debug] 17555#0: *1 aio_read: fd:8 0
2011/09/22 11:12:52 [debug] 17555#0: *1 aio_error: fd:8 36
2011/09/22 11:12:52 [error] 17555#0: *1 http file cache purge: ngx_http_file_cache_open() failed, client: 62.212.230.25, server: cu02.turbo.az, request: "GET /purge/site/autos/view/189902 HTTP/1.1", host: "cu02.turbo.az"
2011/09/22 11:12:52 [debug] 17555#0: *1 http finalize request: 500, "/purge/site/autos/view/189902?" a:1, c:1
2011/09/22 11:12:52 [debug] 17555#0: *1 http special response: 500, "/purge/site/autos/view/189902?"
2011/09/22 11:12:52 [debug] 17555#0: *1 http set discard body
2011/09/22 11:12:52 [debug] 17555#0: *1 posix_memalign: 00000008012E2000:4096 @16
2011/09/22 11:12:52 [debug] 17555#0: *1 HTTP/1.1 500 Internal Server Error
Server: nginx/1.0.6
Date: Thu, 22 Sep 2011 06:12:52 GMT
Content-Type: text/html
Transfer-Encoding: chunked
Connection: close

2011/09/22 11:12:52 [debug] 17555#0: *1 write new buf t:1 f:0 00000008012E2230, pos 00000008012E2230, size: 168 file: 0, size: 0
2011/09/22 11:12:52 [debug] 17555#0: *1 http write filter: l:0 f:0 s:168
2011/09/22 11:12:52 [debug] 17555#0: *1 http output filter "/purge/site/autos/view/189902?"
2011/09/22 11:12:52 [debug] 17555#0: *1 http copy filter: "/purge/site/autos/view/189902?"
2011/09/22 11:12:52 [debug] 17555#0: *1 http copy filter: -2 "/purge/site/autos/view/189902?"
2011/09/22 11:12:52 [debug] 17555#0: *1 http finalize request: -2, "/purge/site/autos/view/189902?" a:1, c:1
2011/09/22 11:12:52 [debug] 17555#0: *1 event timer add: 3: 60000:1316672032115
2011/09/22 11:12:52 [debug] 17555#0: *1 aio event handler fd:8 /home/nginx/cache/0/c6/02ab3c74d93d87556a42990159510c60
2011/09/22 11:12:52 [debug] 17555#0: *1 aio_error: fd:8 0
2011/09/22 11:12:52 [debug] 17555#0: *1 aio_return: fd:8 359
2011/09/22 11:12:52 [debug] 17555#0: *1 http run request: "/purge/site/autos/view/189902?"
2011/09/22 11:12:52 [debug] 17555#0: *1 http writer handler: "/purge/site/autos/view/189902?"
2011/09/22 11:12:52 [debug] 17555#0: *1 http output filter "/purge/site/autos/view/189902?"
2011/09/22 11:12:52 [debug] 17555#0: *1 http copy filter: "/purge/site/autos/view/189902?"
2011/09/22 11:12:52 [debug] 17555#0: *1 http ssi filter "/purge/site/autos/view/189902?"
2011/09/22 11:12:52 [debug] 17555#0: *1 saved: 0 state: 0
2011/09/22 11:12:52 [debug] 17555#0: *1 parse: -2, looked: 0 000000000057FDE0-000000000057FE6C
2011/09/22 11:12:52 [debug] 17555#0: *1 saved: 0
2011/09/22 11:12:52 [debug] 17555#0: *1 saved: 0 state: 0
2011/09/22 11:12:52 [debug] 17555#0: *1 parse: -2, looked: 0 000000000057ED80-000000000057EDB4
2011/09/22 11:12:52 [debug] 17555#0: *1 saved: 0
2011/09/22 11:12:52 [debug] 17555#0: *1 saved: 0 state: 0
2011/09/22 11:12:52 [debug] 17555#0: *1 parse: -2, looked: 0 000000000057EE00-000000000057EF92
2011/09/22 11:12:52 [debug] 17555#0: *1 saved: 0
2011/09/22 11:12:52 [debug] 17555#0: *1 ssi out: 00000008012E2480 000000000057FDE0
2011/09/22 11:12:52 [debug] 17555#0: *1 ssi out: 00000008012E24E0 000000000057ED80
2011/09/22 11:12:52 [debug] 17555#0: *1 ssi out: 00000008012E2540 000000000057EE00
2011/09/22 11:12:52 [debug] 17555#0: *1 http postpone filter "/purge/site/autos/view/189902?" 00000008012E24D0
2011/09/22 11:12:52 [debug] 17555#0: *1 http chunk: 140
2011/09/22 11:12:52 [debug] 17555#0: *1 http chunk: 52
2011/09/22 11:12:52 [debug] 17555#0: *1 http chunk: 402
2011/09/22 11:12:52 [debug] 17555#0: *1 write old buf t:1 f:0 00000008012E2230, pos 00000008012E2230, size: 168 file: 0, size: 0
2011/09/22 11:12:52 [debug] 17555#0: *1 write new buf t:1 f:0 0000000000000000, pos 00000008012E2620, size: 5 file: 0, size: 0
2011/09/22 11:12:52 [debug] 17555#0: *1 write new buf t:0 f:0 0000000000000000, pos 000000000057FDE0, size: 140 file: 0, size: 0
2011/09/22 11:12:52 [debug] 17555#0: *1 write new buf t:0 f:0 0000000000000000, pos 000000000057ED80, size: 52 file: 0, size: 0
2011/09/22 11:12:52 [debug] 17555#0: *1 write new buf t:0 f:0 0000000000000000, pos 000000000057EE00, size: 402 file: 0, size: 0
2011/09/22 11:12:52 [debug] 17555#0: *1 write new buf t:0 f:0 0000000000000000, pos 00000000004740B8, size: 7 file: 0, size: 0
2011/09/22 11:12:52 [debug] 17555#0: *1 http write filter: l:1 f:0 s:774
2011/09/22 11:12:52 [debug] 17555#0: *1 http write filter limit 0
2011/09/22 11:12:52 [debug] 17555#0: *1 writev: 774 of 774
2011/09/22 11:12:52 [debug] 17555#0: *1 http write filter 0000000000000000
2011/09/22 11:12:52 [debug] 17555#0: *1 http copy filter: 0 "/purge/site/autos/view/189902?"
2011/09/22 11:12:52 [debug] 17555#0: *1 http writer output filter: 0, "/purge/site/autos/view/189902?"
2011/09/22 11:12:52 [debug] 17555#0: *1 http writer done: "/purge/site/autos/view/189902?"
2011/09/22 11:12:52 [debug] 17555#0: *1 http finalize request: 0, "/purge/site/autos/view/189902?" a:1, c:1
2011/09/22 11:12:52 [debug] 17555#0: *1 event timer del: 3: 1316672032115
2011/09/22 11:12:52 [debug] 17555#0: *1 http request count:1 blk:0
2011/09/22 11:12:52 [debug] 17555#0: *1 http close request
2011/09/22 11:12:52 [debug] 17555#0: *1 http log handler
2011/09/22 11:12:52 [debug] 17555#0: *1 run cleanup: 00000008012D4C90
2011/09/22 11:12:52 [debug] 17555#0: *1 file cleanup: fd:8
2011/09/22 11:12:52 [debug] 17555#0: *1 run cleanup: 00000008012D4C40
2011/09/22 11:12:52 [debug] 17555#0: *1 http file cache cleanup
2011/09/22 11:12:52 [debug] 17555#0: *1 http file cache free, fd: 8
2011/09/22 11:12:52 [debug] 17555#0: *1 free: 00000008012D4000, unused: 8
2011/09/22 11:12:52 [debug] 17555#0: *1 free: 00000008012E2000, unused: 2344
2011/09/22 11:12:52 [debug] 17555#0: *1 close http connection: 3
2011/09/22 11:12:52 [debug] 17555#0: *1 reusable connection: 0
2011/09/22 11:12:52 [debug] 17555#0: *1 free: 0000000801242800
2011/09/22 11:12:52 [debug] 17555#0: *1 free: 0000000801272700
2011/09/22 11:12:52 [debug] 17555#0: *1 free: 0000000801214200, unused: 8
2011/09/22 11:12:52 [debug] 17555#0: *1 free: 0000000801214400, unused: 128

and following is full log of successful purge (once aio has been disabled)

2011/09/22 11:21:24 [debug] 17682#0: *11 http keepalive handler
2011/09/22 11:21:24 [debug] 17682#0: *11 malloc: 0000000801242800:1024
2011/09/22 11:21:24 [debug] 17682#0: *11 recv: eof:0, avail:602, err:0
2011/09/22 11:21:24 [debug] 17682#0: *11 recv: fd:8 602 of 1024
2011/09/22 11:21:24 [debug] 17682#0: *11 reusable connection: 0
2011/09/22 11:21:24 [debug] 17682#0: *11 malloc: 0000000801272700:1264
2011/09/22 11:21:24 [debug] 17682#0: *11 event timer del: 8: 1316672539285
2011/09/22 11:21:24 [debug] 17682#0: *11 generic phase: 0
2011/09/22 11:21:24 [debug] 17682#0: *11 rewrite phase: 1
2011/09/22 11:21:24 [debug] 17682#0: *11 test location: "/"
2011/09/22 11:21:24 [debug] 17682#0: *11 test location: ~ "/purge(/.*)"
2011/09/22 11:21:24 [debug] 17682#0: *11 using configuration "/purge(/.*)"
2011/09/22 11:21:24 [debug] 17682#0: *11 http cl:-1 max:1048576
2011/09/22 11:21:24 [debug] 17682#0: *11 rewrite phase: 3
2011/09/22 11:21:24 [debug] 17682#0: *11 post rewrite phase: 4
2011/09/22 11:21:24 [debug] 17682#0: *11 generic phase: 5
2011/09/22 11:21:24 [debug] 17682#0: *11 generic phase: 6
2011/09/22 11:21:24 [debug] 17682#0: *11 generic phase: 7
2011/09/22 11:21:24 [debug] 17682#0: *11 access phase: 8
2011/09/22 11:21:24 [debug] 17682#0: *11 access phase: 9
2011/09/22 11:21:24 [debug] 17682#0: *11 post access phase: 10
2011/09/22 11:21:24 [debug] 17682#0: *11 http set discard body
2011/09/22 11:21:24 [debug] 17682#0: *11 http script var: "cu02.turbo.az"
2011/09/22 11:21:24 [debug] 17682#0: *11 http script capture: "/site/autos/view/189902"
2011/09/22 11:21:24 [debug] 17682#0: *11 http cache key: "cu02.turbo.az/site/autos/view/189902"
2011/09/22 11:21:24 [debug] 17682#0: *11 add cleanup: 00000008012D3C40
2011/09/22 11:21:24 [debug] 17682#0: *11 http file cache exists: 0 e:1
2011/09/22 11:21:24 [debug] 17682#0: *11 cache file: "/home/nginx/cache/0/c6/02ab3c74d93d87556a42990159510c60"
2011/09/22 11:21:24 [debug] 17682#0: *11 add cleanup: 00000008012D3C90
2011/09/22 11:21:24 [debug] 17682#0: *11 http file cache fd: 9
2011/09/22 11:21:24 [debug] 17682#0: *11 read: 9, 00000008012D3D10, 359, 0
2011/09/22 11:21:24 [debug] 17682#0: *11 http file cache purge: "/home/nginx/cache/0/c6/02ab3c74d93d87556a42990159510c60" purged
2011/09/22 11:21:24 [debug] 17682#0: *11 posix_memalign: 00000008012E1000:4096 @16
2011/09/22 11:21:24 [debug] 17682#0: *11 HTTP/1.1 200 OK
Server: nginx/1.0.6
Date: Thu, 22 Sep 2011 06:21:24 GMT
Content-Type: text/html
Content-Length: 291
Connection: keep-alive

2011/09/22 11:21:24 [debug] 17682#0: *11 write new buf t:1 f:0 00000008012E1070, pos 00000008012E1070, size: 147 file: 0, size: 0
2011/09/22 11:21:24 [debug] 17682#0: *11 http write filter: l:0 f:0 s:147
2011/09/22 11:21:24 [debug] 17682#0: *11 http output filter "/purge/site/autos/view/189902?"
2011/09/22 11:21:24 [debug] 17682#0: *11 http copy filter: "/purge/site/autos/view/189902?"
2011/09/22 11:21:24 [debug] 17682#0: *11 http postpone filter "/purge/site/autos/view/189902?" 00007FFFFFFFE570
2011/09/22 11:21:24 [debug] 17682#0: *11 write old buf t:1 f:0 00000008012E1070, pos 00000008012E1070, size: 147 file: 0, size: 0
2011/09/22 11:21:24 [debug] 17682#0: *11 write new buf t:1 f:0 00000008012D3EC8, pos 00000008012D3EC8, size: 291 file: 0, size: 0
2011/09/22 11:21:24 [debug] 17682#0: *11 http write filter: l:1 f:0 s:438
2011/09/22 11:21:24 [debug] 17682#0: *11 http write filter limit 0
2011/09/22 11:21:24 [debug] 17682#0: *11 writev: 438 of 438
2011/09/22 11:21:24 [debug] 17682#0: *11 http write filter 0000000000000000
2011/09/22 11:21:24 [debug] 17682#0: *11 http copy filter: 0 "/purge/site/autos/view/189902?"
2011/09/22 11:21:24 [debug] 17682#0: *11 http finalize request: 0, "/purge/site/autos/view/189902?" a:1, c:1
2011/09/22 11:21:24 [debug] 17682#0: *11 set http keepalive handler
2011/09/22 11:21:24 [debug] 17682#0: *11 http close request
2011/09/22 11:21:24 [debug] 17682#0: *11 http log handler
2011/09/22 11:21:24 [debug] 17682#0: *11 run cleanup: 00000008012D3C90
2011/09/22 11:21:24 [debug] 17682#0: *11 file cleanup: fd:9
2011/09/22 11:21:24 [debug] 17682#0: *11 run cleanup: 00000008012D3C40
2011/09/22 11:21:24 [debug] 17682#0: *11 http file cache cleanup
2011/09/22 11:21:24 [debug] 17682#0: *11 http file cache free, fd: 9
2011/09/22 11:21:24 [debug] 17682#0: *11 free: 00000008012D3000, unused: 0
2011/09/22 11:21:24 [debug] 17682#0: *11 free: 00000008012E1000, unused: 3688
2011/09/22 11:21:24 [debug] 17682#0: *11 event timer add: 8: 65000:1316672549345
2011/09/22 11:21:24 [debug] 17682#0: *11 free: 0000000801272700
2011/09/22 11:21:24 [debug] 17682#0: *11 free: 0000000801242800
2011/09/22 11:21:24 [debug] 17682#0: *11 hc free: 0000000000000000 0
2011/09/22 11:21:24 [debug] 17682#0: *11 hc busy: 0000000000000000 0
2011/09/22 11:21:24 [debug] 17682#0: *11 reusable connection: 1
2011/09/22 11:21:24 [debug] 17682#0: *11 http empty handler
PiotrSikora commented 13 years ago

Thanks, I'll add support for AIO in the next few days.

hasanove commented 13 years ago

thanks very much, Piotr, I will disable aio for the time being for my service

if you need help in testing this once completed, I will be happy to assist

PiotrSikora commented 13 years ago

@hasanove: could you try running AIO with git HEAD? Thanks.

hasanove commented 13 years ago

thanks, looks very good, so far no errors :-)

PiotrSikora commented 13 years ago

@hasanove: I've shuffled some things around, it shouldn't make any difference, but it would be great if you could pull git HEAD again.

hasanove commented 13 years ago

I just did another update and see no issues again.

PiotrSikora commented 13 years ago

Great! Thanks for help with debugging and testing this.

I've just released version 1.4 with AIO support, case closed.