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.

Sign up for GitHub

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

Jump to bottom

nginx 1.0.5 / freebsd 8 - error 500 #3

Closed
hasanove opened this issue Aug 3, 2011 · 22 comments
Closed

nginx 1.0.5 / freebsd 8 - error 500 #3

hasanove opened this issue Aug 3, 2011 · 22 comments

Comments

@hasanove
Copy link

hasanove commented Aug 3, 2011

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
Copy link
Contributor

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
Copy link
Author

hasanove commented Aug 4, 2011

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
Copy link
Author

hasanove commented Aug 4, 2011

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

@PiotrSikora
Copy link
Contributor

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

And please provide your configuration.

@hasanove
Copy link
Author

hasanove commented Aug 5, 2011

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
Copy link
Author

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

@PiotrSikora
Copy link
Contributor

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

@hasanove
Copy link
Author

hasanove commented Sep 8, 2011

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

@PiotrSikora
Copy link
Contributor

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

Could you try running git HEAD?

@PiotrSikora
Copy link
Contributor

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

@hasanove
Copy link
Author

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
Copy link
Author

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
Copy link
Contributor

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

@PiotrSikora
Copy link
Contributor

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

@hasanove
Copy link
Author

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
Copy link
Contributor

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

@hasanove
Copy link
Author

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
Copy link
Contributor

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

@hasanove
Copy link
Author

hasanove commented Oct 5, 2011

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

@PiotrSikora
Copy link
Contributor

@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
Copy link
Author

hasanove commented Oct 6, 2011

I just did another update and see no issues again.

@PiotrSikora
Copy link
Contributor

Great! Thanks for help with debugging and testing this.

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

@notr1ch notr1ch mentioned this issue Dec 2, 2014
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@PiotrSikora @hasanove