search

ngsru / nginx-syslog-module

Sends access and error logs over UDP in syslog format.
2 stars 1 forks source link

Segfault with error_page #1

Open splitice opened 11 years ago

splitice commented 11 years ago

Backtrace:

#0  0x080f2ac7 in ngx_http_syslog_error_handler (log=0x8cf4608,
    p=0xbfbae8b8 "\b\353\272\277L<\265\b\346", p_len=1960)
    at /var/x4b/nginx-syslog-module/ngx_http_syslog_module.c:489
489         ngx_http_syslog_common_handler(
(gdb) backtrace full
#0  0x080f2ac7 in ngx_http_syslog_error_handler (log=0x8cf4608,
    p=0xbfbae8b8 "\b\353\272\277L<\265\b\346", p_len=1960)
    at /var/x4b/nginx-syslog-module/ngx_http_syslog_module.c:489
No locals.
#1  0x080f2aea in ngx_http_syslog_error_handler (log=0x0, p=0xa <Address 0xa out of bounds>,
    p_len=3206221928) at /var/x4b/nginx-syslog-module/ngx_http_syslog_module.c:494
No locals.
#2  0x080f2aea in ngx_http_syslog_error_handler (log=0xb7bc7380, p=0xb7bc6ff4 "|-\024",
    p_len=3206222780) at /var/x4b/nginx-syslog-module/ngx_http_syslog_module.c:494
No locals.
#3  0x00000000 in ?? ()

Occurs when error_page is used, tested on a 504 error with config similar to:

@e504 {
    proxy_pass ...;
}

error_page 504 @e504;

nginx version: nginx/1.3.11

splitice commented 11 years ago

after a bit of debugging, I beleive the error occurs when an error is thrown within the named location.

Such as file not found, or any proxy_pass connection error. e.g if you use "location @test { proxy_pass http://10.0.0.1; }" presuming 10.0.0.1 doesnt exist on your network.

splitice commented 11 years ago

and another backtrace generated that looks a bit different.

splitice commented 11 years ago

0 0x080f2b18 in ngx_http_syslog_common_handler (source=2, level=6,

buf=0x8c9d480 "{ibootleg.org:46.17.96.109} ibootleg.org 79.161.51.12 - - [30/Jan/2013:08:25:44 +0400] \"GET /search/valkyria%20chronicles%202 HTTP/1.0\" 504 250 \"-\" \"Mozilla/5.0 (compatible; MJ12bot/v1.4.3; http://www"..., len=229)
at /var/x4b/nginx-syslog-module/ngx_http_syslog_module.c:510
    conf = 0x8c9d565
    ctx = 0x8e22b0c
    map = 0xfe
    i = 23

1 0x080f27dd in ngx_http_syslog_log_request_handler (r=0x8dafba8)

at /var/x4b/nginx-syslog-module/ngx_http_syslog_module.c:381
    line = 0x8c9d480 "{ibootleg.org:46.17.96.109} ibootleg.org 79.161.51.12 - - [30/Jan/2013:08:25:44 +0400] \"GET /search/valkyria%20chronicles%202 HTTP/1.0\" 504 250 \"-\" \"Mozilla/5.0 (compatible; MJ12bot/v1.4.3; http://www"...
    len = 229
    i = 2
    l = 5
    log = 0x1
    lcf = 0x8d80860
    conf = 0x8d80b8c
    map = 0x8d80c1c
    fmt = 0x8d6e96c

2 0x0808e211 in ngx_http_log_request (r=0x8dafba8) at src/http/ngx_http_request.c:3276

    i = 1
    n = 2
    log_handler = 0x8dde11c
    cmcf = 0x8d6e644

3 0x0808e0b9 in ngx_http_free_request (r=0x8dafba8, rc=0)

at src/http/ngx_http_request.c:3229
    log = 0x8cefcd8
    pool = 0xb7bae3a0
    linger = {l_onoff = -1212488768, l_linger = 8}
    cln = 0x0
    ctx = 0xbf8959b8
    clcf = 0xb7ad9d8c

4 0x0808dfa4 in ngx_http_close_request (r=0x8dafba8, rc=0)

at src/http/ngx_http_request.c:3181
    c = 0xb26ed138

5 0x0808dcb6 in ngx_http_lingering_close_handler (rev=0x8e295c0)

at src/http/ngx_http_request.c:3048
    n = 0
    timer = 30
    c = 0xb26ed138
    r = 0x8dafba8
    clcf = 0x1388
    buffer = "F\251\276\267\250\002\317\b\210\003\317\b\000\000\000\000\070\251\277\267\250\002\317\b8\251\277\267XZ\211\277\250\252\276\267\210x\314\b\f\000\000\000\210x\314\bd,\322\267(\362\311\b\300\336\310\b\300\303\306\b\f\000\000\000(\362\311\b\300\336\310\b\254Q\337\b8\251\277\267\210\365\316\b\300\303\306\b\230Z\211\277y\361\276\267\300\303\306\b\000\000\000\000\210x\314\bQ\255\251\267\002\000\211\277\340X\367\267&\210\274\267\250\002\317\b\200\303\306\b\300\336\310\bP\363\311\b8\251\277\267\000\000\000\000\360\327\330\b8[\211\277\066\267\276\267\210\365\316\b\300\303\306\b\360\327\330\bH\242\314\b(\362\311\b\310\247\314\b8[\211\277\002\337\307\267\000\000\000\000\n\000\000\000\350Z\211\277/\247\251\267\000\257\277\267p\330\330\b\300\303\306\b\000\000\000\000\000\000\000\000\250\002\317\b\000\000\000\000\300\303\306\b\000\000\000\0

00\000\000\000\000\250\002\317\b", '\000' <repeats 12 times>"\360, \327\330\b\210\365\316\bH\000\000\000\270\343\272\267\071\000\000\000\000\000\000\000\240\343\272\267\364\317\272\267\240\343\272\267\070\251\277\267\210\365\316\b\360\327\330\b\310[\211\277b\312\276\267\360\327\330\b\200\246\314\b\001\000\000\000\270r\314\b(\362\311\b", '\000' <repeats 20 times>"\253, \347\306\267\070\251\277\267\210\365\316\b`\324\330\b\026f\255\267\062T\275\267", '\000' <repeats 12 times>"\210, \365\316\b\030)\277\267xv\277\267\300\303\306\b\000\000\000\000\000\000\000\000"...

6 0x0806bb0f in ngx_event_process_posted (cycle=0x8d4cad8, posted=0x810fb7c)

at src/event/ngx_event_posted.c:40
    ev = 0x8e295c0

7 0x0806a22b in ngx_process_events_and_timers (cycle=0x8d4cad8) at src/event/ngx_event.c:276

    flags = 3
    timer = 5000
    delta = 40

8 0x08073889 in ngx_worker_process_cycle (cycle=0x8d4cad8, data=0x0)

at src/os/unix/ngx_process_cycle.c:807
    worker = 0
    i = 0
    c = 0xbf896aa8

9 0x08070f37 in ngx_spawn_process (cycle=0x8d4cad8,

proc=0x807376e <ngx_worker_process_cycle>, data=0x0, name=0x80f7408 "worker process",
respawn=-4) at src/os/unix/ngx_process.c:198
    on = 1
    pid = 0
    s = 3

10 0x08072d9c in ngx_start_worker_processes (cycle=0x8d4cad8, n=2, type=-4)

at src/os/unix/ngx_process_cycle.c:362
    i = 0
    ch = {command = 1, pid = 148164076, slot = 147169076, fd = 135288024}

11 0x080729e3 in ngx_master_process_cycle (cycle=0x8d4cad8)

at src/os/unix/ngx_process_cycle.c:249
    title = 0x8d58288 "master process /usr/sbin/nginx"
    p = 0x8d582a6 ""
    size = 31
    i = 1
    n = 0
    sigio = 0
    set = {__val = {0 <repeats 32 times>}}
    itv = {it_interval = {tv_sec = -1208631004, tv_usec = 134681366}, it_value = {
        tv_sec = 13, tv_usec = -1081513056}}
    live = 1
    delay = 0
    ls = 0x6
    ccf = 0x8d4cdec

12 0x0804d847 in main (argc=1, argv=0xbf896df4) at src/core/nginx.c:412

    i = 57
    log = 0x810d894
    cycle = 0x8c596f8
    init_cycle = {conf_ctx = 0x0, pool = 0x8c590b0, log = 0x810d894, new_log = {
        log_level = 0, file = 0x0, connection = 0, handler = 0, 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}, paths = {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 = 21,
        data = 0x80f46f2 "/etc/nginx/nginx.conf"}, conf_param = {len = 0, data = 0x0},
      conf_prefix = {len = 11, data = 0x80f46f2 "/etc/nginx/nginx.conf"}, prefix = {
        len = 5, data = 0x80f46ec "/usr/"}, lock_file = {len = 0, data = 0x0},
      hostname = {len = 0, data = 0x0}}
    ccf = 0x8c59f34
seletskiy commented 11 years ago

Thx for bug report.

Can you attach minimal nginx.conf which reproduces bug, please? I can't reproduce bug just using named locations and error_page directive.

I found some wrong code related with this issue (which I'm fixing for now), but it does not segfaults nginx.

splitice commented 11 years ago

Sure stripping down my testing config now for you.

splitice commented 11 years ago 
upstream does_not_exist {
        server 10.1.77.99;
}
server {
        #just to make timeout quicker
        proxy_read_timeout 2s;
        proxy_connect_timeout 2s;

        listen 88;

        location @e504 {
                internal;
                proxy_pass http://does_not_exist;
        }
        location / {
                root /does_not_exists/;
        }
        error_page 404 @e504;
}

That should do it.

splitice commented 11 years ago

If you require further assistance Ill give you access to a local testing server.

seletskiy commented 11 years ago

I think I fix a bug. If it does not work for you, let me know.

splitice commented 11 years ago

This issue appears to be fixed :) Ill deploy it on a live server tomorrow to confirm but its working fine on my testing server.

splitice commented 11 years ago

69 0x080c1879 in ngx_http_syslog_error_handler (log=0x9a18cf8,

p=0xbfd0bea0 "\343\305\266\t", p_len=1920)
at /var/x4b/nginx-syslog-module/ngx_http_syslog_module.c:501

No locals.

70 0x080c1879 in ngx_http_syslog_error_handler (log=0x9a18cf8,

p=0xbfd0bea0 "\343\305\266\t", p_len=1920)

---Type to continue, or q to quit--- at /var/x4b/nginx-syslog-module/ngx_http_syslog_module.c:501 No locals.

71 0x080c1879 in ngx_http_syslog_error_handler (log=0x9a18cf8,

p=0xbfd0bea0 "\343\305\266\t", p_len=1920)
at /var/x4b/nginx-syslog-module/ngx_http_syslog_module.c:501

No locals.

72 0x080c1879 in ngx_http_syslog_error_handler (log=0x9a18cf8,

p=0xbfd0bea0 "\343\305\266\t", p_len=1920)
at /var/x4b/nginx-syslog-module/ngx_http_syslog_module.c:501

No locals.

73 0x080c1879 in ngx_http_syslog_error_handler (log=0x9a18cf8,

p=0xbfd0bea0 "\343\305\266\t", p_len=1920)
at /var/x4b/nginx-syslog-module/ngx_http_syslog_module.c:501

No locals.

74 0x080c1879 in ngx_http_syslog_error_handler (log=0x9a18cf8,

p=0xbfd0bea0 "\343\305\266\t", p_len=1920)
at /var/x4b/nginx-syslog-module/ngx_http_syslog_module.c:501

No locals.

75 0x080c1879 in ngx_http_syslog_error_handler (log=0x9a18cf8,

p=0xbfd0bea0 "\343\305\266\t", p_len=1920)
at /var/x4b/nginx-syslog-module/ngx_http_syslog_module.c:501

No locals.

76 0x080c1879 in ngx_http_syslog_error_handler (log=0x9a18cf8,

---Type to continue, or q to quit--- p=0xbfd0bea0 "\343\305\266\t", p_len=1920) at /var/x4b/nginx-syslog-module/ngx_http_syslog_module.c:501 No locals.

77 0x080c1879 in ngx_http_syslog_error_handler (log=0x9a18cf8,

p=0xbfd0bea0 "\343\305\266\t", p_len=1920)
at /var/x4b/nginx-syslog-module/ngx_http_syslog_module.c:501

No locals.

78 0x080c1879 in ngx_http_syslog_error_handler (log=0x9a18cf8,

p=0xbfd0bea0 "\343\305\266\t", p_len=1920)
at /var/x4b/nginx-syslog-module/ngx_http_syslog_module.c:501

No locals.

79 0x080c1879 in ngx_http_syslog_error_handler (log=0x9a18cf8,

p=0xbfd0bea0 "\343\305\266\t", p_len=1920)
at /var/x4b/nginx-syslog-module/ngx_http_syslog_module.c:501

No locals.

80 0x080c1879 in ngx_http_syslog_error_handler (log=0x9a18cf8,

p=0xbfd0bea0 "\343\305\266\t", p_len=1920)
at /var/x4b/nginx-syslog-module/ngx_http_syslog_module.c:501

No locals.

81 0x080c1879 in ngx_http_syslog_error_handler (log=0x9a18cf8,

p=0xbfd0bea0 "\343\305\266\t", p_len=1920)
at /var/x4b/nginx-syslog-module/ngx_http_syslog_module.c:501

No locals. ---Type to continue, or q to quit---

82 0x080c1879 in ngx_http_syslog_error_handler (log=0x9a18cf8,

p=0xbfd0bea0 "\343\305\266\t", p_len=1920)
at /var/x4b/nginx-syslog-module/ngx_http_syslog_module.c:501

No locals.

83 0x080c1879 in ngx_http_syslog_error_handler (log=0x9a18cf8,

p=0xbfd0bea0 "\343\305\266\t", p_len=1920)
at /var/x4b/nginx-syslog-module/ngx_http_syslog_module.c:501

No locals.

84 0x080c1879 in ngx_http_syslog_error_handler (log=0x9a18cf8,

p=0xbfd0bea0 "\343\305\266\t", p_len=1920)
at /var/x4b/nginx-syslog-module/ngx_http_syslog_module.c:501

No locals.

85 0x080c1879 in ngx_http_syslog_error_handler (log=0x9a18cf8,

p=0xbfd0bea0 "\343\305\266\t", p_len=1920)
at /var/x4b/nginx-syslog-module/ngx_http_syslog_module.c:501

No locals.

86 0x080c1879 in ngx_http_syslog_error_handler (log=0x9a18cf8,

p=0xbfd0bea0 "\343\305\266\t", p_len=1920)
at /var/x4b/nginx-syslog-module/ngx_http_syslog_module.c:501

No locals.

87 0x080c1879 in ngx_http_syslog_error_handler (log=0x9a18cf8,

p=0xbfd0bea0 "\343\305\266\t", p_len=1920)
at /var/x4b/nginx-syslog-module/ngx_http_syslog_module.c:501

---Type to continue, or q to quit--- No locals.

88 0x080c1879 in ngx_http_syslog_error_handler (log=0x9a18cf8,

p=0xbfd0bea0 "\343\305\266\t", p_len=1920)
at /var/x4b/nginx-syslog-module/ngx_http_syslog_module.c:501

No locals.

89 0x080c1879 in ngx_http_syslog_error_handler (log=0x9a18cf8,

p=0xbfd0bea0 "\343\305\266\t", p_len=1920)
at /var/x4b/nginx-syslog-module/ngx_http_syslog_module.c:501

No locals.

90 0x080c1879 in ngx_http_syslog_error_handler (log=0x9a18cf8,

p=0xbfd0bea0 "\343\305\266\t", p_len=1920)
at /var/x4b/nginx-syslog-module/ngx_http_syslog_module.c:501

No locals.

91 0x080c1879 in ngx_http_syslog_error_handler (log=0x9a18cf8,

p=0xbfd0bea0 "\343\305\266\t", p_len=1920)
at /var/x4b/nginx-syslog-module/ngx_http_syslog_module.c:501

No locals.

92 0x080c1879 in ngx_http_syslog_error_handler (log=0x9a18cf8,

p=0xbfd0bea0 "\343\305\266\t", p_len=1920)
at /var/x4b/nginx-syslog-module/ngx_http_syslog_module.c:501

No locals.

93 0x080c1879 in ngx_http_syslog_error_handler (log=0x9a18cf8,

p=0xbfd0bea0 "\343\305\266\t", p_len=1920)

---Type to continue, or q to quit--- at /var/x4b/nginx-syslog-module/ngx_http_syslog_module.c:501 No locals.

94 0x080c1879 in ngx_http_syslog_error_handler (log=0x9a18cf8,

p=0xbfd0bea0 "\343\305\266\t", p_len=1920)
at /var/x4b/nginx-syslog-module/ngx_http_syslog_module.c:501

No locals.

95 0x080c1879 in ngx_http_syslog_error_handler (log=0x9a18cf8,

p=0xbfd0bea0 "\343\305\266\t", p_len=1920)
at /var/x4b/nginx-syslog-module/ngx_http_syslog_module.c:501

No locals.

96 0x080c1879 in ngx_http_syslog_error_handler (log=0x9a18cf8,

p=0xbfd0bea0 "\343\305\266\t", p_len=1920)
at /var/x4b/nginx-syslog-module/ngx_http_syslog_module.c:501

No locals.

97 0x080c1879 in ngx_http_syslog_error_handler (log=0x9a18cf8,

p=0xbfd0bea0 "\343\305\266\t", p_len=1920)
at /var/x4b/nginx-syslog-module/ngx_http_syslog_module.c:501

No locals.

98 0x080c1879 in ngx_http_syslog_error_handler (log=0x9a18cf8,

p=0xbfd0bea0 "\343\305\266\t", p_len=1920)
at /var/x4b/nginx-syslog-module/ngx_http_syslog_module.c:501

No locals.

99 0x080c1879 in ngx_http_syslog_error_handler (log=0x9a18cf8,

---Type to continue, or q to quit--- p=0xbfd0bea0 "\343\305\266\t", p_len=1920) at /var/x4b/nginx-syslog-module/ngx_http_syslog_module.c:501 No locals.

100 0x080c1879 in ngx_http_syslog_error_handler (log=0x9a18cf8,

p=0xbfd0bea0 "\343\305\266\t", p_len=1920)
at /var/x4b/nginx-syslog-module/ngx_http_syslog_module.c:501

No locals.

101 0x080c1879 in ngx_http_syslog_error_handler (log=0x9a18cf8,

p=0xbfd0bea0 "\343\305\266\t", p_len=1920)
at /var/x4b/nginx-syslog-module/ngx_http_syslog_module.c:501

No locals.

102 0x080c1879 in ngx_http_syslog_error_handler (log=0x9a18cf8,

p=0xbfd0bea0 "\343\305\266\t", p_len=1920)
at /var/x4b/nginx-syslog-module/ngx_http_syslog_module.c:501

No locals.

103 0x080c1879 in ngx_http_syslog_error_handler (log=0x9a18cf8,

p=0xbfd0bea0 "\343\305\266\t", p_len=1920)
at /var/x4b/nginx-syslog-module/ngx_http_syslog_module.c:501

No locals.

104 0x080c1879 in ngx_http_syslog_error_handler (log=0x9a18cf8,

p=0xbfd0bea0 "\343\305\266\t", p_len=1920)
at /var/x4b/nginx-syslog-module/ngx_http_syslog_module.c:501

No locals. ---Type to continue, or q to quit---

105 0x080c1879 in ngx_http_syslog_error_handler (log=0x9a18cf8,

p=0xbfd0bea0 "\343\305\266\t", p_len=1920)
at /var/x4b/nginx-syslog-module/ngx_http_syslog_module.c:501

No locals.

106 0x080c1879 in ngx_http_syslog_error_handler (log=0x9a18cf8,

p=0xbfd0bea0 "\343\305\266\t", p_len=1920)
at /var/x4b/nginx-syslog-module/ngx_http_syslog_module.c:501

No locals.

107 0x080c1879 in ngx_http_syslog_error_handler (log=0x9a18cf8,

p=0xbfd0bea0 "\343\305\266\t", p_len=1920)
at /var/x4b/nginx-syslog-module/ngx_http_syslog_module.c:501

No locals.

108 0x080c1879 in ngx_http_syslog_error_handler (log=0x9a18cf8,

p=0xbfd0bea0 "\343\305\266\t", p_len=1920)
at /var/x4b/nginx-syslog-module/ngx_http_syslog_module.c:501

No locals.

109 0x080c1879 in ngx_http_syslog_error_handler (log=0x9a18cf8,

p=0xbfd0bea0 "\343\305\266\t", p_len=1920)
at /var/x4b/nginx-syslog-module/ngx_http_syslog_module.c:501

No locals.

110 0x080c1879 in ngx_http_syslog_error_handler (log=0x9a18cf8,

p=0xbfd0bea0 "\343\305\266\t", p_len=1920)
at /var/x4b/nginx-syslog-module/ngx_http_syslog_module.c:501

---Type to continue, or q to quit--- No locals.

111 0x080c1879 in ngx_http_syslog_error_handler (log=0x9a18cf8,

p=0xbfd0bea0 "\343\305\266\t", p_len=1920)
at /var/x4b/nginx-syslog-module/ngx_http_syslog_module.c:501

No locals.

112 0x080c1879 in ngx_http_syslog_error_handler (log=0x9a18cf8,

p=0xbfd0bea0 "\343\305\266\t", p_len=1920)
at /var/x4b/nginx-syslog-module/ngx_http_syslog_module.c:501

No locals.

113 0x080c1879 in ngx_http_syslog_error_handler (log=0x9a18cf8,

p=0xbfd0bea0 "\343\305\266\t", p_len=1920)
at /var/x4b/nginx-syslog-module/ngx_http_syslog_module.c:501

No locals.

114 0x080c1879 in ngx_http_syslog_error_handler (log=0x9a18cf8,

p=0xbfd0bea0 "\343\305\266\t", p_len=1920)
at /var/x4b/nginx-syslog-module/ngx_http_syslog_module.c:501

No locals.

115 0x080c1879 in ngx_http_syslog_error_handler (log=0x9a18cf8,

p=0xbfd0bea0 "\343\305\266\t", p_len=1920)
at /var/x4b/nginx-syslog-module/ngx_http_syslog_module.c:501

No locals.

116 0x080c1879 in ngx_http_syslog_error_handler (log=0x9a18cf8,

p=0xbfd0bea0 "\343\305\266\t", p_len=1920)

---Type to continue, or q to quit--- at /var/x4b/nginx-syslog-module/ngx_http_syslog_module.c:501 No locals.

117 0x080c1879 in ngx_http_syslog_error_handler (log=0x9a18cf8,

p=0xbfd0bea0 "\343\305\266\t", p_len=1920)
at /var/x4b/nginx-syslog-module/ngx_http_syslog_module.c:501

No locals.

118 0x080c1879 in ngx_http_syslog_error_handler (log=0x9a18cf8,

p=0xbfd0bea0 "\343\305\266\t", p_len=1920)
at /var/x4b/nginx-syslog-module/ngx_http_syslog_module.c:501

No locals.

119 0x080c1879 in ngx_http_syslog_error_handler (log=0x9a18cf8,

p=0xbfd0bea0 "\343\305\266\t", p_len=1920)
at /var/x4b/nginx-syslog-module/ngx_http_syslog_module.c:501

No locals.

120 0x080c1879 in ngx_http_syslog_error_handler (log=0x9a18cf8,

p=0xbfd0bea0 "\343\305\266\t", p_len=1920)
at /var/x4b/nginx-syslog-module/ngx_http_syslog_module.c:501

No locals.

121 0x080c1879 in ngx_http_syslog_error_handler (log=0x9a18cf8,

p=0xbfd0bea0 "\343\305\266\t", p_len=1920)
at /var/x4b/nginx-syslog-module/ngx_http_syslog_module.c:501

....

seletskiy commented 11 years ago

Do you have error_page directive in your production server?

splitice commented 11 years ago

Yes, the only difference between the two servers is that its proxy_pass call actually works, and that it gets a lot of traffic.

Im currently pushing out a temporary hack fix of

""" if(r->connection->log->handler != ngx_http_syslog_error_handler) ngx_http_syslog_ctx->old_handler = r->connection->log->handler; """

That I think should work temporarily as it does on my testing server, im pushing it to a production server now to confirm.

The config on the production server is something along the lines of """ location / { proxy_pass http://10.0.92.118; } location @e504 {

proxy cache is here but shouldnt matter

rewrite ^ /client/timeout.html break;
proxy_pass http://5.9.192.118;

} error_page 504 @e504 """

That should probably replicate it, I dont have a version without my modification compiled to confirm atm.

EDIT: Crappy hack of a patch by me does seem to work for now as far as I can tell.

splitice commented 11 years ago

Something that might be related now that I think of it, my production server has multiple http blocks with their own full configurations (error_page, logging etc)

e.g

http {

sites doing XYZ

} http {

sites doing ABC

}

maybe that is causing double initialization?

seletskiy commented 11 years ago

Oh, looks like I found a problem. Trying to fix now.

splitice commented 11 years ago

Sounds good, and FYI heres another crash that happened while I was away. This is with my error logging patch applied and appears to be to do with acess_log. Although I havent got any replication instructions at this time.

(gdb) bt full

0 0x080c1485 in ngx_http_syslog_common_handler (

source=<value optimized out>, level=6, buf=<value optimized out>, len=299)
at /var/x4b/nginx-syslog-module/ngx_http_syslog_module.c:518
    conf = 0x40
    ctx = 0x973c050
    i = 21

1 0x080c17c9 in ngx_http_syslog_log_request_handler (r=0x96a9d08)

at /var/x4b/nginx-syslog-module/ngx_http_syslog_module.c:389
    line = 0x96f38fc "{web.dnstracks.com:46.17.97.53} web.dnstracks.com 213.                    126.105.98 - - [31/Jan/2013:10:51:07 +0400] \"POST /web/xmlfeed.php HTTP/1.1\" 2                    00 64 \"-\" \"Mozilla/4.0 (compatible; MSIE 7.0; Windows NT 6.0; Triden"...
    len = <value optimized out>
    i = <value optimized out>
    l = <value optimized out>
    lcf = 0x96c4884
    fmt = <value optimized out>

2 0x0807947b in ngx_http_log_request (r=0x96a9d08)

at src/http/ngx_http_request.c:3276
    i = 1
    n = 2
    cmcf = <value optimized out>

3 0x08079548 in ngx_http_free_request (r=0x96a9d08, rc=6)

at src/http/ngx_http_request.c:3229

---Type to continue, or q to quit--- log = 0x9737a08 pool = linger = {l_onoff = -1079839720, l_linger = 134805417} cln = 0x0

4 0x0807b207 in ngx_http_set_keepalive (r=0x96a9d08)

at src/http/ngx_http_request.c:2658
    tcp_nodelay = <value optimized out>
    rev = 0x9795b64
    b = <value optimized out>
    i = 25
    f = <value optimized out>
    wev = 0x96f3858
    c = 0x974bc6c
    hc = 0x9737a30

5 ngx_http_finalize_connection (r=0x96a9d08)

at src/http/ngx_http_request.c:2348
    clcf = 0x96c4734

6 0x0807bb94 in ngx_http_finalize_request (r=0x96a9d08, rc=0)

at src/http/ngx_http_request.c:2256
    c = 0x974bc6c
    pr = 0x804f13c

7 0x0808999a in ngx_http_upstream_finalize_request (r=0x96a9d08,

u=0x96aa4ac, rc=0) at src/http/ngx_http_upstream.c:3116

---Type to continue, or q to quit--- tp = 0x80d9aa4

8 0x0808a677 in ngx_http_upstream_process_non_buffered_request (r=0x96a9d08,

do_write=<value optimized out>) at src/http/ngx_http_upstream.c:2457
    size = <value optimized out>
    n = <value optimized out>
    rc = <value optimized out>
    downstream = 0x974bc6c
    upstream = 0x974b564
    u = 0x96aa4ac
    clcf = 0x96aa620

9 0x0808a870 in ngx_http_upstream_process_non_buffered_downstream (

r=0x96a9d08) at src/http/ngx_http_upstream.c:2388
    wev = <value optimized out>
    c = <value optimized out>
    u = 0x96aa4ac

10 0x0808cb52 in ngx_http_upstream_send_response (r=0x96a9d08, u=0x96aa4ac)

at src/http/ngx_http_upstream.c:2161
    c = <value optimized out>
    clcf = 0x96c4734
    tcp_nodelay = 134795845
    n = <value optimized out>
    rc = <value optimized out>
    p = <value optimized out>

---Type to continue, or q to quit---

11 ngx_http_upstream_process_header (r=0x96a9d08, u=0x96aa4ac)

at src/http/ngx_http_upstream.c:1657
    n = <value optimized out>
    rc = <value optimized out>
    c = <value optimized out>

12 0x0808a9d8 in ngx_http_upstream_handler (ev=0x19)

at src/http/ngx_http_upstream.c:950
    c = 0x974bc6c
    r = 0xef9fa94f
    u = 0x6

13 0x0806a2bd in ngx_epoll_process_events (cycle=0x9640678, timer=500,

flags=1) at src/event/modules/ngx_epoll_module.c:683
    events = 1
    revents = 5
    instance = 0
    i = 0
    level = <value optimized out>
    err = <value optimized out>
    rev = 0x6
    wev = <value optimized out>
    queue = <value optimized out>
    c = <value optimized out>

14 0x080630e1 in ngx_process_events_and_timers (cycle=0x9640678)

---Type to continue, or q to quit--- at src/event/ngx_event.c:249 flags = 1 timer = 500 delta = 2405402430

15 0x08068f16 in ngx_worker_process_cycle (cycle=0x9640678, data=0x1)

at src/os/unix/ngx_process_cycle.c:807
    i = 0
    c = 0x1

16 0x08067806 in ngx_spawn_process (cycle=0x9640678,

proc=0x8068e5f <ngx_worker_process_cycle>, data=0x1,
name=0x80c534a "worker process", respawn=1)
at src/os/unix/ngx_process.c:198
    on = 1
    pid = 0
    s = 1

17 0x0806971d in ngx_reap_children (cycle=0x9640678)

at src/os/unix/ngx_process_cycle.c:619
    i = 1
    n = 3
    ch = {command = 2, pid = 7579, slot = 1, fd = -1}
    ccf = 0x3

18 ngx_master_process_cycle (cycle=0x9640678)

at src/os/unix/ngx_process_cycle.c:180

---Type to continue, or q to quit--- title = 0x80dbc40 "\233\035" p = size = 1 i = 3 n = sigio = 0 set = {__val = {0 <repeats 32 times>}} itv = {it_interval = {tv_sec = 0, tv_usec = 1}, it_value = { tv_sec = -1208226901, tv_usec = 54}} live = 1 delay = 0 ccf = 0x9640eb4

19 0x0804e7f7 in main (argc=1, argv=0xbfa2f9b4) at src/core/nginx.c:412

    i = <value optimized out>
    log = 0x80d98f4
    cycle = 0x9640678
    init_cycle = {conf_ctx = 0x0, pool = 0x96400b0, log = 0x80d98f4,
      new_log = {log_level = 0, file = 0x0, connection = 0, handler = 0,
        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}, paths = {elts = 0x0, nelts = 0, size = 0,
        nalloc = 0, pool = 0x0}, open_files = {last = 0x0, part = {

---Type to continue, or q to quit--- 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 = 21, data = 0x80c1ea1 "/etc/nginx/nginx.conf"}, conf_param = {len = 0, data = 0x0}, conf_prefix = {len = 11, data = 0x80c1ea1 "/etc/nginx/nginx.conf"}, prefix = {len = 5, data = 0x80c1e9b "/usr/"}, lock_file = {len = 0, data = 0x0}, hostname = {len = 0, data = 0x0}} ccf =

splitice commented 11 years ago

I think it may be reload related. Since my config gets auto reloaded every 10 minutes if there is a change and its on that its crashing at the moment.

seletskiy commented 11 years ago

Try latest commit, please.

splitice commented 11 years ago

I havent seen a crash with it yet, tomorrow ill be AFK but Ill let you know if it does.

splitice commented 11 years ago

Its crashing when a syslog message is being sent while being cycled (reloaded).

(gdb) backtrace full

0 0x080c1555 in ngx_http_syslog_common_handler (

source=<value optimized out>, level=6, buf=<value optimized out>, len=336)
at /var/x4b/nginx-syslog-module/ngx_http_syslog_module.c:553
    conf = 0x40
    ctx = 0x9321bf0
    i = 21

1 0x080c18a6 in ngx_http_syslog_log_request_handler (r=0x90ef528)

at /var/x4b/nginx-syslog-module/ngx_http_syslog_module.c:401
    line = 0x90c81b9 "{adv.dnstracks.com:46.17.97.53} adv.dnstracks.com 149.172.180.246 - - [31/Jan/2013:15:17:00 +0400] \"POST /web/xmlfeeds.php HTTP/1.1\" 200 64 \"-\" \"Mozilla/4.0 (compatible; MSIE 7.0; Windows NT 6.1; WOW6"...
    len = <value optimized out>
    i = <value optimized out>
    l = <value optimized out>
    lcf = 0x90f2cdc
    fmt = <value optimized out>
    ctx = <value optimized out>

2 0x0807947b in ngx_http_log_request (r=0x90ef528)

at src/http/ngx_http_request.c:3276
    i = 1
    n = 2
    cmcf = <value optimized out>

3 0x08079548 in ngx_http_free_request (r=0x90ef528, rc=6)

---Type to continue, or q to quit--- at src/http/ngx_http_request.c:3229 log = 0x90f23b8 pool = linger = {l_onoff = -1074343832, l_linger = 134805417} cln = 0x0

4 0x0807b207 in ngx_http_set_keepalive (r=0x90ef528)

at src/http/ngx_http_request.c:2658
    tcp_nodelay = <value optimized out>
    rev = 0x924a7b0
    b = <value optimized out>
    i = 25
    f = <value optimized out>
    wev = 0x90f04ac
    c = 0x9201308
    hc = 0x90f23e0

5 ngx_http_finalize_connection (r=0x90ef528)

at src/http/ngx_http_request.c:2348
    clcf = 0x90f2b8c

6 0x0807bb94 in ngx_http_finalize_request (r=0x90ef528, rc=0)

at src/http/ngx_http_request.c:2256
    c = 0x9201308
    pr = 0x804f13c

7 0x0808999a in ngx_http_upstream_finalize_request (r=0x90ef528,

---Type to continue, or q to quit--- u=0x90efccc, rc=0) at src/http/ngx_http_upstream.c:3116 tp = 0x80d9cd0

8 0x0808a677 in ngx_http_upstream_process_non_buffered_request (r=0x90ef528,

do_write=<value optimized out>) at src/http/ngx_http_upstream.c:2457
    size = <value optimized out>
    n = <value optimized out>
    rc = <value optimized out>
    downstream = 0x9201308
    upstream = 0x9202adc
    u = 0x90efccc
    clcf = 0x90efe40

9 0x0808a870 in ngx_http_upstream_process_non_buffered_downstream (

r=0x90ef528) at src/http/ngx_http_upstream.c:2388
    wev = <value optimized out>
    c = <value optimized out>
    u = 0x90efccc

10 0x0808cb52 in ngx_http_upstream_send_response (r=0x90ef528, u=0x90efccc)

at src/http/ngx_http_upstream.c:2161
    c = <value optimized out>
    clcf = 0x90f2b8c
    tcp_nodelay = 0
    n = <value optimized out>
    rc = <value optimized out>

---Type to continue, or q to quit--- p =

11 ngx_http_upstream_process_header (r=0x90ef528, u=0x90efccc)

at src/http/ngx_http_upstream.c:1657
    n = <value optimized out>
    rc = <value optimized out>
    c = <value optimized out>

12 0x0808a9d8 in ngx_http_upstream_handler (ev=0x19)

at src/http/ngx_http_upstream.c:950
    c = 0x9201308
    r = 0x35463838
    u = 0x6

13 0x0806325a in ngx_event_process_posted (cycle=0x918a6b8, posted=0x80dbcdc)

at src/event/ngx_event_posted.c:40
    ev = 0x35463838

14 0x0806314b in ngx_process_events_and_timers (cycle=0x918a6b8)

at src/event/ngx_event.c:276
    flags = 3
    timer = <value optimized out>
    delta = 2421355341

15 0x08068f16 in ngx_worker_process_cycle (cycle=0x918a6b8, data=0x1)

at src/os/unix/ngx_process_cycle.c:807
    i = 0
    c = 0x2

---Type to continue, or q to quit---

16 0x08067806 in ngx_spawn_process (cycle=0x918a6b8,

proc=0x8068e5f <ngx_worker_process_cycle>, data=0x1,
name=0x80c544a "worker process", respawn=-4)
at src/os/unix/ngx_process.c:198
    on = 1
    pid = 0
    s = 2

17 0x0806841b in ngx_start_worker_processes (cycle=0x918a6b8, n=6, type=25)

at src/os/unix/ngx_process_cycle.c:362
    i = 1
    ch = {command = 1, pid = 24533, slot = 1, fd = 59}

18 0x08069acf in ngx_master_process_cycle (cycle=0x918a6b8)

at src/os/unix/ngx_process_cycle.c:249
    title = 0x80dbde0 "\327_"
    p = <value optimized out>
    size = 6
    i = 6
    n = <value optimized out>
    sigio = 0
    set = {__val = {0 <repeats 32 times>}}
    itv = {it_interval = {tv_sec = 0, tv_usec = 1}, it_value = {
        tv_sec = -1208792149, tv_usec = 54}}
    live = 1

---Type to continue, or q to quit--- delay = 0 ccf = 0x918a9cc

19 0x0804e7f7 in main (argc=1, argv=0xbff6d634) at src/core/nginx.c:412

    i = <value optimized out>
    log = 0x80d99f4
    cycle = 0x90a8688
    init_cycle = {conf_ctx = 0x0, pool = 0x90a80b0, log = 0x80d99f4,
      new_log = {log_level = 0, file = 0x0, connection = 0, handler = 0,
        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}, paths = {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 = 21,
        data = 0x80c1fa1 "/etc/nginx/nginx.conf"}, conf_param = {len = 0,
        data = 0x0}, conf_prefix = {len = 11,
        data = 0x80c1fa1 "/etc/nginx/nginx.conf"}, prefix = {len = 5,
        data = 0x80c1f9b "/usr/"}, lock_file = {len = 0, data = 0x0},
      hostname = {len = 0, data = 0x0}}

---Type to continue, or q to quit--

seletskiy commented 11 years ago

Hmmm. Can you reproduce it on testing environment. I've tried, but I can't reproduce it using siege and nc. Attaching with gdb to a single worker and then reload. It is not crashing...

splitice commented 11 years ago

Ill try to create a minimum working config on saturday for replication. It definately has something to do with a syslog being sent while the process is being reloaded.

splitice commented 11 years ago

Ok replication instructions.

CONFIG:

syslog_target x4b {
        10.0.0.1;
}
log_format combined_syslog '{$host:$server_addr} $host $remote_addr - $remote_user [$time_local] "$request" $status $body_bytes_sent "$http_referer"';
syslog_map access x4b combined_syslog;
server {
        #just to make timeout quicker
        proxy_read_timeout 10s;
        proxy_connect_timeout 10s;

        listen 88;

        location / {
                proxy_set_header Host ibootleg.org;
                proxy_pass http://46.17.96.109;
        }
}

Steps:

  1. run "ab -c 20 -n 1000 http://127.0.0.1:88/" This will ensure there are always connections at various states in processing at all times.
  2. In another window, keep reloading nginx repeatedly. Or use a command like: while true; do nginx -s reload; done; on a multicore machine.
  3. Watch the error log for the crash.

It is definately annoying to replicate and syslogs attempted to being sent during a reload.

seletskiy commented 11 years ago

I'm still out of luck. Running it for hours and can't get even one crash at reload.

I'm running out of ideas...

What ./configuration options did you use to build nginx?

splitice commented 11 years ago

--prefix=/usr --conf-path=/etc/nginx/nginx.conf --sbin-path=/usr/sbin --with-http_sub_module --http-log-path=/var/log/nginx/access.log --error-log-path=/var/log/nginx/error.log --pid-path=/var/run/nginx.pid --lock-path=/var/lock/nginx.lock --http-client-body-temp-path=/var/lib/nginx/body --http-proxy-temp-path=/var/lib/nginx/proxy --http-fastcgi-temp-path=/var/tmp/nginx/fastcgi --with-ipv6 --with-http_ssl_module --with-http_stub_status_module --without-http_uwsgi_module --without-http_scgi_module --without-http_memcached_module --with-http_xslt_module --add-module=/var/x4b/nginx-syslog-module

Its a pain to reproduce even for me (it happens on my production server about once every three hours). lll try and find some better reproduction steps that always work.

Additionally i get socket leakage on reload, that much is always reproducible and may be relevant?

splitice commented 11 years ago

By the way I by leaked sockets I am refering to messages like

2013/02/04 18:59:19 [alert] 3404#0: open socket #13 left in connection 5
2013/02/04 18:59:19 [alert] 3404#0: aborting

This problem seems to get worse over time as I had a server this morning dropping every incomming connection.

seletskiy commented 11 years ago

I'm trying to fix this issue (leaked udp sockets) right now, but I don't see how it possible could be linked with segfault. Moreover, I don't see how reloading could be linked with this issue, because of while reloading process data is not modified by some way, it's just a HUP signal that arrive to a process.

splitice commented 11 years ago

hmm well it only seems to occur when events are processed from within the ngx_worker_process_cycle context. Im trying to find a more reliable replication instruction but atm are unable to find something that causes the issue consistantly.

I can provide full GDB cores if it will help (to get locals and stuff).