nginx-udplog-module
nginx-udplog-module copied to clipboard
Published
20 hours ago •
vkholodkov
vkholodkov
Segfault when using access_udplog in multiple locations
I'm having issues with nginx children segfaulting while using access_udplog. Debugging output and backtrace below. Any help would be appreciated.
DEBUG LOG
===================================
2012/10/24 16:35:57 [debug] 74865#0: bind() 0.0.0.0:80 #6
2012/10/24 16:35:57 [debug] 74865#0: counter: 0000000800761080, 1
2012/10/24 16:35:57 [debug] 74866#0: bind() 0.0.0.0:80 #6
2012/10/24 16:35:57 [notice] 74866#0: using the "kqueue" event method
2012/10/24 16:35:57 [debug] 74866#0: counter: 0000000800761080, 1
2012/10/24 16:35:57 [notice] 74866#0: nginx/1.2.4
2012/10/24 16:35:57 [notice] 74866#0: OS: FreeBSD 9.0-RELEASE-p3
2012/10/24 16:35:57 [notice] 74866#0: kern.osreldate: 900044, built on 900044
2012/10/24 16:35:57 [notice] 74866#0: hw.ncpu: 1
2012/10/24 16:35:57 [notice] 74866#0: net.inet.tcp.sendspace: 32768
2012/10/24 16:35:57 [notice] 74866#0: kern.ipc.somaxconn: 128
2012/10/24 16:35:57 [notice] 74866#0: getrlimit(RLIMIT_NOFILE): 3434:3434
2012/10/24 16:35:57 [debug] 74867#0: write: 7, 00007FFFFFFFD860, 6, 0
2012/10/24 16:35:57 [notice] 74867#0: start worker processes
2012/10/24 16:35:57 [debug] 74867#0: channel 3:7
2012/10/24 16:35:57 [notice] 74867#0: start worker process 74868
2012/10/24 16:35:57 [debug] 74867#0: sigsuspend
2012/10/24 16:35:57 [debug] 74868#0: malloc: 0000000801C61000:16384
2012/10/24 16:35:57 [debug] 74868#0: malloc: 0000000801C75000:16384
2012/10/24 16:35:57 [debug] 74868#0: malloc: 0000000801C79000:16384
2012/10/24 16:35:57 [debug] 74868#0: malloc: 0000000801DC0000:204800
2012/10/24 16:35:57 [debug] 74868#0: malloc: 0000000801E05000:114688
2012/10/24 16:35:57 [debug] 74868#0: malloc: 0000000801E21000:114688
2012/10/24 16:35:57 [debug] 74868#0: kevent set event: 6: ft:-1 fl:0005
2012/10/24 16:35:57 [debug] 74868#0: kevent set event: 7: ft:-1 fl:0005
2012/10/24 16:35:57 [debug] 74868#0: worker cycle
2012/10/24 16:35:57 [debug] 74868#0: kevent timer: -1, changes: 2
2012/10/24 16:37:01 [debug] 74868#0: kevent events: -1
2012/10/24 16:37:01 [info] 74868#0: kevent() failed (4: Interrupted system call)
2012/10/24 16:37:01 [debug] 74868#0: timer delta: 63603
2012/10/24 16:37:01 [debug] 74868#0: posted events 0000000000000000
2012/10/24 16:37:01 [debug] 74868#0: worker cycle
2012/10/24 16:37:01 [debug] 74868#0: kevent timer: -1, changes: 0
2012/10/24 16:37:19 [debug] 74868#0: kevent events: 1
2012/10/24 16:37:19 [debug] 74868#0: kevent: 6: ft:-1 fl:0000 ff:00000000 d:2 ud:0000000801E05000
2012/10/24 16:37:19 [debug] 74868#0: accept on 0.0.0.0:80, ready: 2
2012/10/24 16:37:19 [debug] 74868#0: posix_memalign: 0000000801C1D200:256 @16
2012/10/24 16:37:19 [debug] 74868#0: *1 accept: 10.5.5.38 fd:3
2012/10/24 16:37:19 [debug] 74868#0: *1 event timer add: 3: 60000:1351111099456
2012/10/24 16:37:19 [debug] 74868#0: *1 kevent set event: 3: ft:-1 fl:0025
2012/10/24 16:37:19 [debug] 74868#0: posix_memalign: 0000000801C1D300:256 @16
2012/10/24 16:37:19 [debug] 74868#0: *2 accept: 10.5.5.38 fd:9
2012/10/24 16:37:19 [debug] 74868#0: *2 event timer add: 9: 60000:1351111099456
2012/10/24 16:37:19 [debug] 74868#0: *2 kevent set event: 9: ft:-1 fl:0025
2012/10/24 16:37:19 [debug] 74868#0: timer delta: 18288
2012/10/24 16:37:19 [debug] 74868#0: posted events 0000000000000000
2012/10/24 16:37:19 [debug] 74868#0: worker cycle
2012/10/24 16:37:19 [debug] 74868#0: kevent timer: 60000, changes: 2
2012/10/24 16:37:19 [debug] 74868#0: kevent events: 1
2012/10/24 16:37:19 [debug] 74868#0: kevent: 3: ft:-1 fl:0020 ff:00000000 d:411 ud:0000000801E050E0
2012/10/24 16:37:19 [debug] 74868#0: *1 malloc: 0000000801D8F600:1256
2012/10/24 16:37:19 [debug] 74868#0: *1 posix_memalign: 0000000801C1D400:256 @16
2012/10/24 16:37:19 [debug] 74868#0: *1 malloc: 0000000801C49800:1024
2012/10/24 16:37:19 [debug] 74868#0: *1 posix_memalign: 0000000801CF2000:4096 @16
2012/10/24 16:37:19 [debug] 74868#0: *1 http process request line
2012/10/24 16:37:19 [debug] 74868#0: *1 recv: eof:0, avail:411, err:0
2012/10/24 16:37:19 [debug] 74868#0: *1 recv: fd:3 411 of 1024
2012/10/24 16:37:19 [debug] 74868#0: *1 http request line: "GET /test1/index.html HTTP/1.1"
2012/10/24 16:37:19 [debug] 74868#0: *1 http uri: "/test1/index.html"
2012/10/24 16:37:19 [debug] 74868#0: *1 http args: ""
2012/10/24 16:37:19 [debug] 74868#0: *1 http exten: "html"
2012/10/24 16:37:19 [debug] 74868#0: *1 http process request header line
2012/10/24 16:37:19 [debug] 74868#0: *1 http header: "Host: 10.5.5.63"
2012/10/24 16:37:19 [debug] 74868#0: *1 http header: "Connection: keep-alive"
2012/10/24 16:37:19 [debug] 74868#0: *1 http header: "Cache-Control: max-age=0"
2012/10/24 16:37:19 [debug] 74868#0: *1 http header: "User-Agent: Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.4 (KHTML, like Gecko) Chrome/22.0.1229.94 Safari/537.4"
2012/10/24 16:37:19 [debug] 74868#0: *1 http header: "Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8"
2012/10/24 16:37:19 [debug] 74868#0: *1 http header: "Accept-Encoding: gzip,deflate,sdch"
2012/10/24 16:37:19 [debug] 74868#0: *1 http header: "Accept-Language: en-US,en;q=0.8"
2012/10/24 16:37:19 [debug] 74868#0: *1 http header: "Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.3"
2012/10/24 16:37:19 [debug] 74868#0: *1 http header done
2012/10/24 16:37:19 [debug] 74868#0: *1 event timer del: 3: 1351111099456
2012/10/24 16:37:19 [debug] 74868#0: *1 rewrite phase: 0
2012/10/24 16:37:19 [debug] 74868#0: *1 test location: "/"
2012/10/24 16:37:19 [debug] 74868#0: *1 test location: "test2"
2012/10/24 16:37:19 [debug] 74868#0: *1 test location: "test1"
2012/10/24 16:37:19 [debug] 74868#0: *1 using configuration "/test1"
2012/10/24 16:37:19 [debug] 74868#0: *1 http cl:-1 max:1048576
2012/10/24 16:37:19 [debug] 74868#0: *1 rewrite phase: 2
2012/10/24 16:37:19 [debug] 74868#0: *1 http script value: "12345"
2012/10/24 16:37:19 [debug] 74868#0: *1 http script set $subid
2012/10/24 16:37:19 [debug] 74868#0: *1 post rewrite phase: 3
2012/10/24 16:37:19 [debug] 74868#0: *1 generic phase: 4
2012/10/24 16:37:19 [debug] 74868#0: *1 generic phase: 5
2012/10/24 16:37:19 [debug] 74868#0: *1 access phase: 6
2012/10/24 16:37:19 [debug] 74868#0: *1 access phase: 7
2012/10/24 16:37:19 [debug] 74868#0: *1 post access phase: 8
2012/10/24 16:37:19 [debug] 74868#0: *1 content phase: 9
2012/10/24 16:37:19 [debug] 74868#0: *1 content phase: 10
2012/10/24 16:37:19 [debug] 74868#0: *1 content phase: 11
2012/10/24 16:37:19 [debug] 74868#0: *1 content phase: 12
2012/10/24 16:37:19 [debug] 74868#0: *1 http filename: "/usr/local/www/nginx/test1/index.html"
2012/10/24 16:37:19 [debug] 74868#0: *1 add cleanup: 0000000801CF2B48
2012/10/24 16:37:19 [error] 74868#0: *1 open() "/usr/local/www/nginx/test1/index.html" failed (2: No such file or directory), client: 10.5.5.38, server: localhost, request: "GET /test1/index.html HTTP/1.1", host: "10.5.5.63"
2012/10/24 16:37:19 [debug] 74868#0: *1 http finalize request: 404, "/test1/index.html?" a:1, c:1
2012/10/24 16:37:19 [debug] 74868#0: *1 http special response: 404, "/test1/index.html?"
2012/10/24 16:37:19 [debug] 74868#0: *1 http set discard body
2012/10/24 16:37:19 [debug] 74868#0: *1 HTTP/1.1 404 Not Found
Server: nginx/1.2.4
Date: Wed, 24 Oct 2012 20:37:19 GMT
Content-Type: text/html
Content-Length: 570
Connection: close
2012/10/24 16:37:19 [debug] 74868#0: *1 write new buf t:1 f:0 0000000801CF2BC8, pos 0000000801CF2BC8, size: 149 file: 0, size: 0
2012/10/24 16:37:19 [debug] 74868#0: *1 http write filter: l:0 f:0 s:149
2012/10/24 16:37:19 [debug] 74868#0: *1 http output filter "/test1/index.html?"
2012/10/24 16:37:19 [debug] 74868#0: *1 http copy filter: "/test1/index.html?"
2012/10/24 16:37:19 [debug] 74868#0: *1 http postpone filter "/test1/index.html?" 0000000801CF2DE0
2012/10/24 16:37:19 [debug] 74868#0: *1 write old buf t:1 f:0 0000000801CF2BC8, pos 0000000801CF2BC8, size: 149 file: 0, size: 0
2012/10/24 16:37:19 [debug] 74868#0: *1 write new buf t:0 f:0 0000000000000000, pos 0000000000707D40, size: 116 file: 0, size: 0
2012/10/24 16:37:19 [debug] 74868#0: *1 write new buf t:0 f:0 0000000000000000, pos 0000000000707640, size: 52 file: 0, size: 0
2012/10/24 16:37:19 [debug] 74868#0: *1 write new buf t:0 f:0 0000000000000000, pos 00000000007076C0, size: 402 file: 0, size: 0
2012/10/24 16:37:19 [debug] 74868#0: *1 http write filter: l:1 f:0 s:719
2012/10/24 16:37:19 [debug] 74868#0: *1 http write filter limit 0
2012/10/24 16:37:19 [debug] 74868#0: *1 writev: 719 of 719
2012/10/24 16:37:19 [debug] 74868#0: *1 http write filter 0000000000000000
2012/10/24 16:37:19 [debug] 74868#0: *1 http copy filter: 0 "/test1/index.html?"
2012/10/24 16:37:19 [debug] 74868#0: *1 http finalize request: 0, "/test1/index.html?" a:1, c:1
2012/10/24 16:37:19 [debug] 74868#0: *1 http request count:1 blk:0
2012/10/24 16:37:19 [debug] 74868#0: *1 http close request
2012/10/24 16:37:19 [debug] 74868#0: *1 http log handler
2012/10/24 16:37:19 [debug] 74868#0: *1 http udplog handler
2012/10/24 16:37:19 [debug] 74868#0: *1 posix_memalign: 0000000801CF4000:4096 @16
BACKTRACE
=======================================
Program received signal SIGSEGV, Segmentation fault.
0x00000000004dce64 in ngx_http_udplogger_send (l=0x801c6d020,
buf=0x801cf4020 "10.5.5.38 - - [24/Oct/2012:16:37:19 -0400] \"GET /test1/index.html HTTP/1.1\" 404 570 \"-\" \"Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.4 (KHTML, like Gecko) Chrome/22.0.1229.94 Safari/537.4\"", len=196) at /usr/ports/www/nginx/work/nginx_udplog_module-1.0.0/ngx_http_udplog_module.c:373
373 /usr/ports/www/nginx/work/nginx_udplog_module-1.0.0/ngx_http_udplog_module.c: No such file or directory.
(gdb) bt full
#0 0x00000000004dce64 in ngx_http_udplogger_send (l=0x801c6d020,
buf=0x801cf4020 "10.5.5.38 - - [24/Oct/2012:16:37:19 -0400] \"GET /test1/index.html HTTP/1.1\" 404 570 \"-\" \"Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.4 (KHTML, like Gecko) Chrome/22.0.1229.94 Safari/537.4\"", len=196) at /usr/ports/www/nginx/work/nginx_udplog_module-1.0.0/ngx_http_udplog_module.c:373
n = -1
uc = 0x0
#1 0x00000000004dcc41 in ngx_http_udplog_handler (r=0x801d8f600) at /usr/ports/www/nginx/work/nginx_udplog_module-1.0.0/ngx_http_udplog_module.c:302
line = 0x801cf4020 "10.5.5.38 - - [24/Oct/2012:16:37:19 -0400] \"GET /test1/index.html HTTP/1.1\" 404 570 \"-\" \"Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.4 (KHTML, like Gecko) Chrome/22.0.1229.94 Safari/537.4\""
p = 0x801cf40e4 ""
len = 271
i = 16
l = 0
pri = 190
tag = {len = 5, data = 0x4f256e "nginx"}
log = 0x801c6cf48
op = 0x801c5efb8
ulcf = 0x801c6cb40
time = 1351111039
tm = {tm_sec = 19, tm_min = 37, tm_hour = 20, tm_mday = 24, tm_mon = 10, tm_year = 2012, tm_wday = 3, tm_yday = 8, tm_isdst = 197, tm_gmtoff = 0,
tm_zone = 0x7fffffffd270 "\260\322\377\377\377\177"}
#2 0x0000000000458d87 in ngx_http_log_request (r=0x801d8f600) at src/http/ngx_http_request.c:3082
i = 1
n = 2
log_handler = 0x801c73f18
cmcf = 0x801c5e920
#3 0x0000000000458c17 in ngx_http_free_request (r=0x801d8f600, rc=0) at src/http/ngx_http_request.c:3037
log = 0x801c1d260
linger = {l_onoff = -11424, l_linger = 32767}
cln = 0x0
ctx = 0x801c6bcb8
clcf = 0x2
#4 0x0000000000458aa9 in ngx_http_close_request (r=0x801d8f600, rc=0) at src/http/ngx_http_request.c:2990
c = 0x801dc0190
#5 0x0000000000456f00 in ngx_http_finalize_connection (r=0x801d8f600) at src/http/ngx_http_request.c:2220
clcf = 0x801c6bcb8
#6 0x0000000000456b03 in ngx_http_finalize_request (r=0x801d8f600, rc=0) at src/http/ngx_http_request.c:2114
c = 0x801dc0190
pr = 0x801c6f9f0
clcf = 0x801c6bcb8
#7 0x0000000000456682 in ngx_http_finalize_request (r=0x801d8f600, rc=404) at src/http/ngx_http_request.c:2001
c = 0x801dc0190
pr = 0x801c6bfc8
clcf = 0x801c6bcb8
#8 0x0000000000448698 in ngx_http_core_content_phase (r=0x801d8f600, ph=0x801c74a98) at src/http/ngx_http_core_module.c:1406
root = 18446744073709551611
rc = 404
path = {len = 34389576248, data = 0x801d8f600 "HTTP"}
#9 0x0000000000447142 in ngx_http_core_run_phases (r=0x801d8f600) at src/http/ngx_http_core_module.c:877
rc = -2
ph = 0x801c74978
cmcf = 0x801c5e920
#10 0x00000000004470bd in ngx_http_handler (r=0x801d8f600) at src/http/ngx_http_core_module.c:860
cmcf = 0x801e050e0
#11 0x0000000000455dd4 in ngx_http_process_request (r=0x801d8f600) at src/http/ngx_http_request.c:1685
c = 0x801dc0190
#12 0x00000000004547d5 in ngx_http_process_request_headers (rev=0x801e050e0) at src/http/ngx_http_request.c:1135
p = 0x10 <Address 0x10 out of bounds>
len = 34390089728
n = 379
rc = 0
rv = 140737488344480
h = 0x801cf2750
c = 0x801dc0190
hh = 0x0
r = 0x801d8f600
cscf = 0x801c696f8
cmcf = 0x801c5e920
#13 0x0000000000453f66 in ngx_http_process_request_line (rev=0x801e050e0) at src/http/ngx_http_request.c:933
host = 0x801cf2000 "'/\317\001\b"
n = 411
rc = 0
rv = 128
c = 0x801dc0190
r = 0x801d8f600
cscf = 0x801cf2580
#14 0x000000000045316b in ngx_http_init_request (rev=0x801e050e0) at src/http/ngx_http_request.c:519
tp = 0x718ba0 <cached_time+96>
i = 1
c = 0x801dc0190
r = 0x801d8f600
sin = 0x900000020
port = 0x801c74ad8
addr = 0x801c74ae8
ctx = 0x801c1d2a0
addr_conf = 0x801c74af0
hc = 0x801c1d2b8
cscf = 0x801c696f8
clcf = 0x801c69790
cmcf = 0x801c5e920
sin6 = 0x4e2c88
addr6 = 0x801c79000
#15 0x000000000043cc70 in ngx_kqueue_process_events (cycle=0x801c5d050, timer=60000, flags=1) at src/event/modules/ngx_kqueue_module.c:684
events = 1
n = 2
i = 0
instance = 0
level = 60000
err = 0
ev = 0x801e050e0
queue = 0x801e05110
ts = {tv_sec = 60, tv_nsec = 0}
tp = 0x7fffffffd710
#16 0x000000000042bd2c in ngx_process_events_and_timers (cycle=0x801c5d050) at src/event/ngx_event.c:247
flags = 1
timer = 60000
delta = 1351111039456
#17 0x0000000000439304 in ngx_worker_process_cycle (cycle=0x801c5d050, data=0x0) at src/os/unix/ngx_process_cycle.c:808
i = 1
c = 0x7fffffffd840
#18 0x0000000000436301 in ngx_spawn_process (cycle=0x801c5d050, proc=0x439110 <ngx_worker_process_cycle>, data=0x0, name=0x4e2499 "worker process", respawn=-3) at src/os/unix/ngx_process.c:198
on = 1
pid = 0
s = 0
#19 0x000000000043816a in ngx_start_worker_processes (cycle=0x801c5d050, n=1, type=-3) at src/os/unix/ngx_process_cycle.c:365
i = 0
ch = {command = 1, pid = 1, slot = 140737488345440, fd = -9264}
#20 0x00000000004377f9 in ngx_master_process_cycle (cycle=0x801c5d050) at src/os/unix/ngx_process_cycle.c:137
title = 0x801c74b73 "master process /usr/local/sbin/nginx"
p = 0x801c74b97 ""
size = 37
i = 1
n = 34389479528
sigio = 0
set = {__bits = {0, 0, 0, 0}}
itv = {it_interval = {tv_sec = 0, tv_usec = 0}, it_value = {tv_sec = 0, tv_usec = 0}}
live = 0
delay = 0
ls = 0x6
ccf = 0x801c5e0b0
#21 0x0000000000406693 in main (argc=1, argv=0x7fffffffdbc0) at src/core/nginx.c:410
i = 67
log = 0x718a80 <ngx_log>
cycle = 0x801c5d050
init_cycle = {conf_ctx = 0x0, pool = 0x801c49800, log = 0x718a80 <ngx_log>, new_log = {log_level = 0, file = 0x0, connection = 0, handler = 0x0, data = 0x0, action = 0x0}, files = 0x0,
free_connections = 0x0, free_connection_n = 0, reusable_connections_queue = {prev = 0x0, next = 0x0}, listening = {elts = 0x0, nelts = 0, size = 0, nalloc = 0, pool = 0x0}, pathes = {
elts = 0x0, nelts = 0, size = 0, nalloc = 0, pool = 0x0}, open_files = {last = 0x0, part = {elts = 0x0, nelts = 0, next = 0x0}, size = 0, nalloc = 0, pool = 0x0}, shared_memory = {
last = 0x0, part = {elts = 0x0, nelts = 0, next = 0x0}, size = 0, nalloc = 0, pool = 0x0}, connection_n = 0, files_n = 0, connections = 0x0, read_events = 0x0, write_events = 0x0,
old_cycle = 0x0, conf_file = {len = 31, data = 0x4de608 "/usr/local/etc/nginx/nginx.conf"}, conf_param = {len = 0, data = 0x0}, conf_prefix = {len = 21,
data = 0x4de608 "/usr/local/etc/nginx/nginx.conf"}, prefix = {len = 21, data = 0x4de5f0 "/usr/local/etc/nginx/"}, lock_file = {len = 0, data = 0x0}, hostname = {len = 0, data = 0x0}}
ccf = 0x801c5e0b0
FULL CONFIG
===================================================================
worker_processes 1;
error_log /var/log/nginx-error.log debug;
events {
worker_connections 1024;
}
http {
include mime.types;
default_type application/octet-stream;
sendfile on;
keepalive_timeout 65;
server {
listen 80;
server_name localhost;
location / {
root /usr/local/www/nginx;
index index.html index.htm;
}
location /test1 {
root /usr/local/www/nginx;
index index.html index.htm;
set $subid 12345;
access_udplog 127.0.0.1:2466 combined bare;
}
location /test2 {
root /usr/local/www/nginx;
index index.html index.htm;
set $subid 12345;
access_udplog 127.0.0.1:2466 combined bare;
}
location /test3 {
root /usr/local/www/nginx;
index index.html index.htm;
set $subid 12345;
access_udplog 127.0.0.1:2466 combined bare;
}
error_page 500 502 503 504 /50x.html;
location = /50x.html {
root /usr/local/www/nginx-dist;
}
}
}
COMPILE OPTIONS
===================================================================
# nginx -V
nginx version: nginx/1.2.4
TLS SNI support enabled
configure arguments: --prefix=/usr/local/etc/nginx --with-cc-opt='-I /usr/local/include' --with-ld-opt='-L /usr/local/lib' --conf-path=/usr/local/etc/nginx/nginx.conf --sbin-path=/usr/local/sbin/nginx --pid-path=/var/run/nginx.pid --error-log-path=/var/log/nginx-error.log --user=www --group=www --with-debug --with-file-aio --with-ipv6 --http-client-body-temp-path=/var/tmp/nginx/client_body_temp --http-fastcgi-temp-path=/var/tmp/nginx/fastcgi_temp --http-proxy-temp-path=/var/tmp/nginx/proxy_temp --http-scgi-temp-path=/var/tmp/nginx/scgi_temp --http-uwsgi-temp-path=/var/tmp/nginx/uwsgi_temp --http-log-path=/var/log/nginx-access.log --with-http_flv_module --with-http_geoip_module --with-http_mp4_module --with-http_secure_link_module --with-http_stub_status_module --with-pcre --add-module=/usr/ports/www/nginx/work/arut-nginx-rtmp-module-f7f24ba --add-module=/usr/ports/www/nginx/work/nginx_udplog_module-1.0.0 --with-http_ssl_module
