Attempts to automatically reload GeoIP database without auto_reload parameter configured about ngx_http_geoip2_module HOT 18 CLOSED

I'm running the same test with
#59 for a few hours, and everything looks fine so far. Will provide an update once we're done.

from ngx_http_geoip2_module.

Thanks for reporting and fixing @defanator. Will await your next update.

from ngx_http_geoip2_module.

So, 24 hours pen. testing didn't show anything weird in the lab. I'll try to pick some time to investigate segfaults on MMDB reloads under heavy load later, but for now I think #59 can be merged as it clearly helps to avoid garbage in ngx_http_geoip2_db_t.check_interval and ngx_stream_geoip2_db_t.check_interval.

from ngx_http_geoip2_module.

Thank you, I have merged #59. I'll continue looking into the segfaults as well, but I do wonder if they were related.

from ngx_http_geoip2_module.

Have you experienced any more segfaults since running the updated version @defanator?

from ngx_http_geoip2_module.

@leev I haven't updated the .so yet, hopefully will do it later today (GMT+3).

from ngx_http_geoip2_module.

@leev I have installed modified modules yesterday. Good news is that there were no more attempts to reload MMDB without auto_reload configuration option. Bad news is that when I've added the auto_reload 5s; and tried to do touch on local MMDB file a couple of times, I got the same segfault again:

Program terminated with signal SIGSEGV, Segmentation fault.
#0  0x0000563be887e920 in ngx_http_log_escape (src=0x7f41bf8be53c <error: Cannot access memory at address 0x7f41bf8be53c>, size=<optimized out>, dst=0x0)
    at src/http/modules/ngx_http_log_module.c:1023
1023	src/http/modules/ngx_http_log_module.c: No such file or directory.
(gdb) bt
#0  0x0000563be887e920 in ngx_http_log_escape (src=0x7f41bf8be53c <error: Cannot access memory at address 0x7f41bf8be53c>, size=<optimized out>, dst=0x0)
    at src/http/modules/ngx_http_log_module.c:1023
#1  0x0000563be887eaba in ngx_http_log_escape (size=<optimized out>, src=<optimized out>, dst=0x0) at src/http/modules/ngx_http_log_module.c:962
#2  ngx_http_log_variable_getlen (r=<optimized out>, data=<optimized out>) at src/http/modules/ngx_http_log_module.c:962
#3  0x0000563be88805fa in ngx_http_log_handler (r=0x563bea6e38a0) at src/http/modules/ngx_http_log_module.c:305
#4  0x0000563be8875cd0 in ngx_http_log_request (r=r@entry=0x563bea6e38a0) at src/http/ngx_http_request.c:3728
#5  0x0000563be8877671 in ngx_http_free_request (r=r@entry=0x563bea6e38a0, rc=rc@entry=0) at src/http/ngx_http_request.c:3675
#6  0x0000563be887822e in ngx_http_set_keepalive (r=0x563bea6e38a0) at src/http/ngx_http_request.c:3091
#7  ngx_http_finalize_connection (r=<optimized out>) at src/http/ngx_http_request.c:2742
#8  0x0000563be8889c3d in ngx_http_upstream_process_request (r=0x563bea6e38a0, u=0x563bea6e4d78) at src/http/ngx_http_upstream.c:4292
#9  0x0000563be8888d18 in ngx_http_upstream_handler (ev=<optimized out>) at src/http/ngx_http_upstream.c:1344
#10 0x0000563be886123b in ngx_epoll_process_events (cycle=<optimized out>, timer=<optimized out>, flags=<optimized out>) at src/event/modules/ngx_epoll_module.c:902
#11 0x0000563be885753a in ngx_process_events_and_timers (cycle=cycle@entry=0x563be9fdc5b0) at src/event/ngx_event.c:279
#12 0x0000563be885f361 in ngx_worker_process_cycle (cycle=cycle@entry=0x563be9fdc5b0, data=data@entry=0x0) at src/os/unix/ngx_process_cycle.c:785
#13 0x0000563be885d708 in ngx_spawn_process (cycle=cycle@entry=0x563be9fdc5b0, proc=0x563be885f2e0 <ngx_worker_process_cycle>, data=0x0, name=0x563be89305ac "worker process", 
    respawn=respawn@entry=0) at src/os/unix/ngx_process.c:199
#14 0x0000563be8860444 in ngx_reap_children (cycle=0x563be9fdc5b0) at src/os/unix/ngx_process_cycle.c:657
#15 ngx_master_process_cycle (cycle=0x563be9fdc5b0) at src/os/unix/ngx_process_cycle.c:186
#16 0x0000563be8835698 in main (argc=<optimized out>, argv=<optimized out>) at src/core/nginx.c:382
(gdb) 

Let me know if it would be better to create separate issue, or we can continue here.

I'll try to dig a bit deeper in order to get possible reasons of SIGSEGV on reloading.

from ngx_http_geoip2_module.

@leev please check #61 and let me know your opinion on that.

I'm currently running synthetic tests before applying that change to one of our live balancers.

from ngx_http_geoip2_module.

@leev while synthetic tests have been running fine for a few hours, it's still segfaulting under real load (that said, with #61 applied). Backtrace is the same.

Appreciate any input.

from ngx_http_geoip2_module.

I'll share simplified nginx configuration which can be used for reproducing SIGSEGV locally (my understanding here is that it could be easily triggered with some sort of delayed requests in pair with quick ones using the same log format).

from ngx_http_geoip2_module.

Ok it was a bit harder than I thought. Minimal configuration to reproduce:

load_module modules/ngx_http_geoip2_module.so;

user nginx;
worker_processes 1;
error_log /var/log/nginx/error.log info;
pid /var/run/nginx.pid;

events {
    worker_connections 16000;
}

http {
    default_type application/octet-stream;

    access_log off;
    sendfile off;
    root /usr/share/nginx/html;

    set_real_ip_from 127.0.0.1;
    set_real_ip_from 10.10.0.0/16;

    geoip2 /var/lib/GeoIP/GeoLite2-City.mmdb {
	auto_reload 1s;
        $geoip_country_code country iso_code;
        $geoip_country_name country names en;
    }

    log_format  geoip '$remote_addr [$time_local] $status $geoip_country_code '
                      '"$geoip_country_name"';

    map $geoip_country_code $geoip_deny {
        "XX" 1;
        "YY" 1;
        "ZZ" 1;
        default 0;
    }

    server {
        listen 80;
        server_name localhost;
        access_log /var/log/nginx/geoip.log geoip;

        if ($geoip_deny) {
            return 444;
        }

        location / {
            limit_rate 200k;
        }
    }
}

wrk command:

wrk -t 2 -c 20 -d 10m -s geoip-test.lua http://localhost/512kb

(512kb is a stub file generated by dd like this: dd if=/dev/urandom of=512kb bs=1k count=512)

I'm getting SIGSEGV's immediately after touch'ing MMDB files while wrk is running with the above configuration.

Working on a fix currently.

from ngx_http_geoip2_module.

@leev I've just added this one to #61:
80659b1

With that change in place, I can't reproduce segfaults any longer.

Going to push updated modules to live balancers and check there as well a bit later.

from ngx_http_geoip2_module.

Thank you for digging into this @defanator. Will review the PR soon. Let me know the results from running on your live load balancers.

from ngx_http_geoip2_module.

@leev it is running without any issues for ~12 hours already. I think we're covered now.

from ngx_http_geoip2_module.

Thanks @defanator. I tried running your patch with just 80659b1 and that appears to fix the issue (without needing 26399de). Do you think the reloading should still be moved to the logging phase?

from ngx_http_geoip2_module.

@leev good question! I've been thinking about this since we finally figured out the root cause of segfaults.

Finally, I think that doing reload checks at logging phase is better than calling it on every access to a variable due to consistency reasons (i.e. consider a situation when a reload happens in the middle of composing log line using a set of variables obtained from MMDB, and corresponding parts of new MMDB have changed in comparison to previous one).

from ngx_http_geoip2_module.

Yeah that makes sense. Lets get it in. Thanks for all your work fixing this.

from ngx_http_geoip2_module.

Fixed in #61. 3.2 released.

from ngx_http_geoip2_module.