Header filter race condition #153
Description
I'm attempting to do some more processing in a header filter, from which I was previously only doing a few assoc!s. Now I'm calling out to an external service which can add anywhere from 5 to 500ms latency depending on conditions. I've started seeing segfaults in the JVM and also Nginx since doing this. At least I think this is what's causing it. I'm not totally sure. The JVM crashes happened with v0.4.4 and the Nginx crash just happened with master (1f9ec02). nginx-1.8.1 for both. Not sure if these are bugs, or I'm just confused about how to properly write a blocking handler. I thought nginx would hold the request until it got a response from the handler, but maybe this isn't true?
Nginx error output:
2017-01-02 14:21:45[error][10222][main]#37387440: request is release!
2017/01/02 14:21:45 [error] 10222#0: ngx clojure: ngx_http_clojure_handle_post_event failed,rp=37387440u, rc=500
*** Error in `nginx: worker process': malloc(): memory corruption: 0x00000000023a5e90 ***
======= Backtrace: =========
/lib/x86_64-linux-gnu/libc.so.6(+0x777e5)[0x7fda2e4097e5]
/lib/x86_64-linux-gnu/libc.so.6(+0x8181e)[0x7fda2e41381e]
/lib/x86_64-linux-gnu/libc.so.6(__libc_malloc+0x54)[0x7fda2e4155d4]
/lib/x86_64-linux-gnu/libc.so.6(posix_memalign+0x220)[0x7fda2e418c70]
nginx: worker process[0x4251e4]
nginx: worker process[0x409a18]
nginx: worker process[0x409d02]
nginx: worker process[0x409eb9]
nginx: worker process[0x43d9dd]
nginx: worker process[0x422edb]
nginx: worker process[0x42b2b3]
nginx: worker process[0x421fd8]
nginx: worker process[0x42a452]
nginx: worker process[0x408ae3]
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf0)[0x7fda2e3b2830]
nginx: worker process[0x407069]
======= Memory map: ========
[...]
Example JVM crash stacktrace, which came from a write to the header map:
Register to memory mapping:
RAX=0x0000000000000060 is an unknown value
RBX={method} {0x00007f5446700e88} 'ngx_http_clojure_mem_copy_to_addr' '(Ljava/lang/Object;JJJ)V' in 'nginx/clojure/NginxClojureRT'
RCX=0x00000000f7922120 is an oop
[error occurred during error reporting (printing register info), id 0xb]
Stack: [0x00007f54355a4000,0x00007f54356a5000], sp=0x00007f54356a2f48, free space=1019k
Native frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code)
C [libc.so.6+0x14d41a]
j nginx.clojure.NginxClojureRT.pushString(JLjava/lang/String;Ljava/nio/charset/Charset;J)I+54
j nginx.clojure.NginxClojureRT.pushNGXString(JLjava/lang/String;Ljava/nio/charset/Charset;J)I+41
j nginx.clojure.TableEltHeaderHolder.push(JJLjava/lang/Object;)V+102
j nginx.clojure.java.JavaLazyHeaderMap.put(Ljava/lang/String;Ljava/lang/Object;)Ljava/lang/Object;+157
j nginx.clojure.clj.LazyHeaderMap.assoc(Ljava/lang/Object;Ljava/lang/Object;)Lnginx/clojure/clj/LazyHeaderMap;+97
j nginx.clojure.clj.LazyHeaderMap.assoc(Ljava/lang/Object;Ljava/lang/Object;)Lclojure/lang/ITransientAssociative;+26
J 4301 C1 clojure.core$assoc_BANG_.invoke(Ljava/lang/Object;Ljava/lang/Object;Ljava/lang/Object;)Ljava/lang/Object; (13 bytes) @ 0x00007f5448fb4bec [0x00007f5448fb49a0+0x24c]
j tileprox.nginx$header.invokeStatic(Ljava/lang/Object;Ljava/lang/Object;Ljava/lang/Object;)Ljava/lang/Object;+383
j tileprox.nginx$header.invoke(Ljava/lang/Object;Ljava/lang/Object;Ljava/lang/Object;)Ljava/lang/Object;+9
j nginx.clojure.clj.NginxClojureHandler.process(Lnginx/clojure/NginxRequest;)Lnginx/clojure/NginxResponse;+61
j nginx.clojure.NginxSimpleHandler.handleRequest(Lnginx/clojure/NginxRequest;)Lnginx/clojure/NginxResponse;+96
j nginx.clojure.NginxSimpleHandler$1.call()Lnginx/clojure/NginxClojureRT$WorkerResponseContext;+59
j nginx.clojure.NginxSimpleHandler$1.call()Ljava/lang/Object;+24
J 3934 C1 java.util.concurrent.FutureTask.run()V (126 bytes) @ 0x00007f5448e8ec4c [0x00007f5448e8ea00+0x24c]
j java.util.concurrent.Executors$RunnableAdapter.call()Ljava/lang/Object;+4
J 3934 C1 java.util.concurrent.FutureTask.run()V (126 bytes) @ 0x00007f5448e8ec4c [0x00007f5448e8ea00+0x24c]
j java.util.concurrent.ThreadPoolExecutor.runWorker(Ljava/util/concurrent/ThreadPoolExecutor$Worker;)V+95
j java.util.concurrent.ThreadPoolExecutor$Worker.run()V+5
j java.lang.Thread.run()V+49
v ~StubRoutines::call_stub
V [libjvm.so+0x66088b]
V [libjvm.so+0x65de74]
V [libjvm.so+0x65e457]