Segfaults (in shmtx_lock) due to mixed module loading/memory design

[wdoekes]

Hi,

the following snippet segfaults:

load_module /path/to/objs/ngx_nchan_module.so;
events {}
#http {}

If I uncomment http {}, it does not crash.

It crashes because:

• first ngx_http module calls the postconfig hooks (nchan_postconfig -> nchan_store_init_postconfig), which initializes shm (shm_create)
• nginx then calls nchan_init_module, which expects shm to be initialized

  
  static ngx_http_module_t  nchan_module_ctx = {
  nchan_add_variables,           /* preconfiguration */
  nchan_postconfig,              /* postconfiguration */  // <-- first this is called
  nchan_create_main_conf,        /* create main configuration */
  NULL,                          /* init main configuration */
  nchan_create_srv_conf,         /* create server configuration */
  nchan_merge_srv_conf,          /* merge server configuration */
  nchan_create_loc_conf,         /* create location configuration */
  nchan_merge_loc_conf,          /* merge location configuration */
  };

ngx_module_t ngx_nchan_module = { NGX_MODULE_V1, &nchan_module_ctx, / module context / nchan_commands, / module directives / NGX_HTTP_MODULE, / module type / NULL, / init master / nchan_init_module, / init module / // <-- then this is called nchan_init_worker, / init process / NULL, / init thread / NULL, / exit thread / nchan_exit_worker, / exit process / nchan_exit_master, / exit master / NGX_MODULE_V1_PADDING };

^-- reference

Apparently it is quite rare to *both* use "init module" *and* "module context".

If there is no `http` block, the ngx_http module never calls the shm_create, creating a partially initialized module and then a crash. (nchan_store_memory.init_module() expects shm to be valid.)

Further, the `shm` (and the global_redis_enabled among others) are static globals. This means that once they are set, they do not get unset, unless they're appropriately overridden.

For instance, if you were to check whether shm is set before continuing in init_module, that would only work _until_ it is set once. Imaging one updating the config, and doing a SIGHUP:
- config with http block (shm is created and works)
- config without http block (shm is not created, but shm variable points to old memory -> crash)

And as the `ngx_http_module_t` has no exit hook (AFAICT), you cannot clear the memory before the second invocation. (The module exit handler runs on the spawned children only, not on the parent.)

(There's a similar situation going on with global_redis_enabled, which only gets set, but never unset. But that is probably for another ticket.)

I'm not at all intimate with this code, and I did not find a trivial fix here.

- perhaps the shm should be attached the ngx_cycle instead of being a global
- init_module should probably not be using anything allocated by postconfig, unless it can check whether postconfig was actually called

[slact]

Good catch and very nice writeup. As for the fix -- I dare say you're overthinking it. The problem is the result of a hack, so what better way to fix it than with an equally ugly hack?

( fixed in 05898226 )

[slact]

And just in case you're curious, there's a need for using both postconfig and init_module hooks, and for the former to depend on the latter. Nchan uses an IPC system that needs to initialize with identiacal ngx_process_slots, and it needs to do this before the fork() into workers. The only way to do this is as a 2-stage process of saving the configured number of workers from in the postconfig() phase, then using it to create shared sockets in init_module. There's also stuff in there about sniffing the number of workers required to generate the channel keyspace sharding function which is necessary for handling nginx reloads and worker crashes.

[wdoekes]

Hi! Thanks for the quick reply.

I actually tried (almost literally) that patch before you created it and ran into the problems I described.

Starting nginx now works:

$ cat segfault.conf 
load_module /home/walter/src/nginx/objs/ngx_nchan_module.so;
events {}
#http{}

$ sudo  ./objs/nginx -t -c `pwd`/segfault.conf
nginx: the configuration file /home/walter/src/nginx/segfault.conf syntax is ok
nginx: configuration file /home/walter/src/nginx/segfault.conf test is successful

$ sudo ./objs/nginx -g 'error_log /dev/stderr info;' -c `pwd`/segfault.conf
2019/02/28 09:16:20 [notice] 5877#5877: using the "epoll" event method
2019/02/28 09:16:20 [notice] 5877#5877: nginx/1.14.2
2019/02/28 09:16:20 [notice] 5877#5877: built by gcc 7.3.0 (Ubuntu 7.3.0-27ubuntu1~18.04) 
2019/02/28 09:16:20 [notice] 5877#5877: OS: Linux 4.15.0-45-generic
2019/02/28 09:16:20 [notice] 5877#5877: getrlimit(RLIMIT_NOFILE): 1024:4096
2019/02/28 09:16:20 [notice] 5878#5878: start worker processes
2019/02/28 09:16:20 [notice] 5878#5878: start worker process 5879

$ pgrep nginx
5878
5879

But stopping does not work exactly as intended (core dumped) when there's no #http, as it crashes in nchan_exit_worker.

$ sudo pkill nginx 
2019/02/28 09:16:47 [notice] 5878#5878: signal 15 (SIGTERM) received from 5898, exiting
2019/02/28 09:16:47 [notice] 5879#5879: signal 15 (SIGTERM) received from 5898, exiting
2019/02/28 09:16:47 [info] 5879#5879: epoll_wait() failed (4: Interrupted system call)
2019/02/28 09:16:47 [notice] 5879#5879: exiting
2019/02/28 09:16:47 [notice] 5878#5878: signal 14 (SIGALRM) received
2019/02/28 09:16:47 [notice] 5878#5878: signal 17 (SIGCHLD) received from 5879
2019/02/28 09:16:47 [alert] 5878#5878: worker process 5879 exited on signal 11 (core dumped)
2019/02/28 09:16:47 [notice] 5878#5878: exit

(gdb) bt
#0  rbtree_empty (seed=0x0, callback=callback@entry=0x7fc2235fde6f <shutdown_walker>, data=data@entry=0x0)
    at /home/walter/src/nginx/../osso-docker-nginx/modules/nchan/src/util/nchan_rbtree.c:308
#1  0x00007fc2235fe5da in memstore_groups_shutdown (gp=<optimized out>)
    at /home/walter/src/nginx/../osso-docker-nginx/modules/nchan/src/store/memory/groups.c:55
#2  0x00007fc223602de8 in nchan_store_exit_worker (cycle=0x559fa166bf30)
    at /home/walter/src/nginx/../osso-docker-nginx/modules/nchan/src/store/memory/memstore.c:1748
#3  0x00007fc2235d3bcb in nchan_exit_worker (cycle=0x559fa166bf30)
    at /home/walter/src/nginx/../osso-docker-nginx/modules/nchan/src/nchan_setup.c:928
#4  0x0000559fa08e9002 in ngx_worker_process_exit (cycle=cycle@entry=0x559fa166bf30)
    at src/os/unix/ngx_process_cycle.c:985
#5  0x0000559fa08e9c76 in ngx_worker_process_cycle (cycle=cycle@entry=0x559fa166bf30, data=data@entry=0x0)
    at src/os/unix/ngx_process_cycle.c:754

As shame to have it crash on shutdown. But it gets worse as the HUP scenario I described also applies:

$ sed -i -e 's/^#http/http/' segfault.conf 

$ sudo ./objs/nginx -g 'error_log /dev/stderr info;' -c `pwd`/segfault.conf
nginx: [warn] could not build optimal variables_hash, you should increase either variables_hash_max_size: 1024 or variables_hash_bucket_size: 64; ignoring variables_hash_bucket_size
2019/02/28 09:46:03 [notice] 7312#7312: using the "epoll" event method
2019/02/28 09:46:03 [notice] 7312#7312: nginx/1.14.2
2019/02/28 09:46:03 [notice] 7312#7312: built by gcc 7.3.0 (Ubuntu 7.3.0-27ubuntu1~18.04) 
2019/02/28 09:46:03 [notice] 7312#7312: OS: Linux 4.15.0-45-generic
2019/02/28 09:46:03 [notice] 7312#7312: getrlimit(RLIMIT_NOFILE): 1024:4096
2019/02/28 09:46:03 [notice] 7313#7313: start worker processes
2019/02/28 09:46:03 [notice] 7313#7313: start worker process 7314

$ pgrep nginx
7313
7314

And now:

$ sed -i -e 's/^http/#http/' segfault.conf 

$ sudo pkill -HUP nginx
2019/02/28 09:46:53 [notice] 7314#7314: signal 1 (SIGHUP) received from 7324, ignoring
2019/02/28 09:46:53 [notice] 7313#7313: signal 1 (SIGHUP) received from 7324, reconfiguring
2019/02/28 09:46:53 [info] 7314#7314: epoll_wait() failed (4: Interrupted system call)
2019/02/28 09:46:53 [notice] 7313#7313: reconfiguring
2019/02/28 09:46:53 [notice] 7313#7313: using the "epoll" event method
2019/02/28 09:46:53 [notice] 7313#7313: start worker processes
2019/02/28 09:46:53 [notice] 7313#7313: start worker process 7325
2019/02/28 09:46:53 [notice] 7313#7313: signal 17 (SIGCHLD) received from 7325
2019/02/28 09:46:53 [notice] 7314#7314: gracefully shutting down
2019/02/28 09:46:53 [alert] 7313#7313: worker process 7325 exited on signal 11 (core dumped)
2019/02/28 09:46:53 [notice] 7314#7314: exiting
2019/02/28 09:46:53 [notice] 7314#7314: exit
2019/02/28 09:46:53 [notice] 7313#7313: start worker process 7327
2019/02/28 09:46:53 [notice] 7313#7313: signal 29 (SIGIO) received
2019/02/28 09:46:53 [notice] 7313#7313: signal 17 (SIGCHLD) received from 7314
2019/02/28 09:46:53 [notice] 7313#7313: worker process 7314 exited with code 0
2019/02/28 09:46:53 [notice] 7313#7313: signal 29 (SIGIO) received
2019/02/28 09:46:53 [notice] 7313#7313: signal 17 (SIGCHLD) received from 7327
2019/02/28 09:46:53 [alert] 7313#7313: worker process 7327 exited on signal 11 (core dumped)
2019/02/28 09:46:53 [notice] 7313#7313: start worker process 7328
2019/02/28 09:46:53 [notice] 7313#7313: signal 17 (SIGCHLD) received from 7328
2019/02/28 09:46:53 [alert] 7313#7313: worker process 7328 exited on signal 11 (core dumped)
2019/02/28 09:46:53 [notice] 7313#7313: start worker process 7329
2019/02/28 09:46:53 [notice] 7313#7313: signal 17 (SIGCHLD) received from 7329
2019/02/28 09:46:53 [alert] 7313#7313: worker process 7329 exited on signal 11 (core dumped)

... and repeat.

As PID 7313 forever keeps the (new) global_nchan_enabled to true (like the global_redis_enabled I mentioned):

#2  0x00007fe874a7a5a7 in nchan_store_init_worker (cycle=<optimized out>)
    at /home/walter/src/nginx/../osso-docker-nginx/modules/nchan/src/store/memory/memstore.c:698
#3  0x00007fe874a4dc46 in nchan_init_worker (cycle=0x56282b848f40)
    at /home/walter/src/nginx/../osso-docker-nginx/modules/nchan/src/nchan_setup.c:53
#4  0x0000562829bed6d0 in ngx_worker_process_init (cycle=cycle@entry=0x56282b848f40, worker=worker@entry=0)
    at src/os/unix/ngx_process_cycle.c:931
#5  0x0000562829bedbfb in ngx_worker_process_cycle (cycle=cycle@entry=0x56282b848f40, data=data@entry=0x0)
    at src/os/unix/ngx_process_cycle.c:735

And it will (again) try to use unconfigured shm.

Thanks for the detailed explanation BTW.

The only way to do this is as a 2-stage process of saving the configured number of workers from in the postconfig() phase, then using it to create shared sockets in init_module.

Yes, I figured as much. I was looking into storing the information gathered from the conf (in postconfig) onto conf->cycle, to make it accessible from init_module, and doing the actual allocations first there. But that quickly grew over my head :grimacing:

[slact]

oh, of course. my bad. 4894af7e

[wdoekes]

Ok, 4894af7 fixes loading/reloading when you don't alter the existence of the http{} block.

That should fix 99% of peoples issues.

I'll leave the ticket for you to decide whether you want to fix the segfault-loop problem as well. At least it won't affect unchanging configs anymore. TY

[slact]

99% wasn't good enough. 105adcd3 should complete this fix.

[wdoekes]

Should, but doesn't.

The problem is that none of the ngx_http_module_t members are called. So after switching from http to #http, preconfig won't be called either, and we'll get the segfault-loop anyway.

[slact]

Odd, It worked in my tests... I started nginx with an http block, thencommented it out, and SUGHUP'd the nginx master.

Specifically, this is what I'm testing with:

worker_processes  4;
worker_rlimit_nofile 150000;

#error_log  /dev/stderr debug;                                                                                                                                            
error_log  stderr notice;
#error_log   err.log  notice;                                                                                                                                             

pid        /tmp/nchan-test-nginx.pid;
daemon      off;

events {
  worker_connections  50000;
}
stream {
    server {
        listen 8081;
        proxy_pass 127.0.0.1:10323;
    }
}
#http {
#    server {
#       listen 8082;
#       location / {
#           proxy_pass http://127.0.0.1:10345;
#       }
#    }
#}

[slact]

for reference, nginx -V:

nginx version: nginx/1.15.6 (no pool)
built with OpenSSL 1.1.1a  20 Nov 2018
TLS SNI support enabled
configure arguments: --with-stream --prefix=/etc/nginx --sbin-path=/usr/bin/nginx --pid-path=/run/nginx.pid --lock-path=/run/nginx.lock --http-client-body-temp-path=/tmp/client_body_temp --http-proxy-temp-path=/tmp/proxy_temp --http-fastcgi-temp-path=/tmp/fastcgi_temp --http-uwsgi-temp-path=/tmp/uwsgi_temp --http-log-path=/dev/stdout --error-log-path=errors.log --with-http_ssl_module --add-module=../nchan --user=http --group=http --http-scgi-temp-path=/tmp/scgi_temp

[slact]

Ah, I see, when built as a dynamic module, preconfig isn't run automatically. Guess I'm up to 99.5%, but not quite 100%.

[slact]

okay then, another hack for good measure: 02df0bae . I've confirmed this working on dynamic module builds, and doesn't break anything down to Nginx 1.6.x.

[wdoekes]

That hack looks like it should do the trick indeed :1st_place_medal:

(There's a similar situation going on with global_redis_enabled, which only gets set, but never unset. But that is probably for another ticket.)

I assume (http) preconfig is called first after nchan_commands are called, or? Otherwise the preconfig could use some 0-setting as well, and then the above would be fixed too..