HTTP: enhanced access log with conditional filtering.

[hongzhidao]

HTTP: enhanced access log with conditional filtering. This feature allows users to specify conditions to control if access log should be recorded. The "if" option supports a string and JavaScript code. If its value is empty, 0, false, null, or undefined, the logs will not be recorded. And the '!' as a prefix inverses the condition.

For example:

    {
        "access_log": {
        "if": "`${new Date().getHours() < 22}`",
        "path": "/path/access.log"
        }
    }

Or

    {
        "access_log": {
        "if": "!`${new Date().getHours() >= 22}`",
        "path": "/path/access.log"
        }
    }

If the current hour is less than 22, the logs will be recorded.

Closes: https://github.com/nginx/unit/issues/594

[ac000]

Hi @hongzhidao

Just some initial general questions (without even having looked at the code yet)

1) Was this a user requested feature?

2) Have you got a real-world example of how this might be used?

3) Is this condition checked for every log attempt?

[andrey-zelenkov]

Looks like it make sense to mention https://github.com/nginx/unit/issues/594 here.

[hongzhidao]

Hi @ac000,

Was this a user requested feature? Have you got a real-world example of how this might be used?

Yep, like @andrey-zelenkov mentioned. And it's also from the nginx's experience. https://nginx.org/en/docs/http/ngx_http_log_module.html

Is this condition checked for every log attempt?

If users enable the access log, it is. The if is part of the access logging.

[ac000]

Thanks, I have a better picture of what this is about now...

I would like to at least see the examples (and descriptions) from https://github.com/nginx/unit/issues/594#issuecomment-1772283239 in the commit message, I'm sure @lcrilly won't mind if you uplift them...

Besides being a little more descriptive, the examples are (for me at least) more tangible. For example I'm not entirely sure what args.log refers to, the only thing that comes to mind is https://example.com/?log=on but I may be way off...

A link to that issue would also be good (even if it's just a Closes: https://github.com/nginx/unit/issues/594)

[ac000]

Generally, personally, I would do a patch or patches that adds the core feature then another patch that hooks it up to the config system.

But it's a relatively small patch, so I'll leave that up to you...

[hongzhidao]

Hi @ac000, Should we keep the first comment on the PR the same as the commit log? And I reworked the example, thanks for the suggestion.

[ac000]

Good question.

For a single patch, it certainly doesn't hurt...

[ac000]

You can remove the <>'s from the URL in the Closes tag, that way GH will recognise it and auto close the issue...

[ac000]

Do these kinds of things work with this patch?

[hongzhidao]

Do these kinds of things work with this patch?

Yes.

[hongzhidao]

Hi @andrey-zelenkov, Welcome to add tests on it, and there are a few examples here. https://github.com/nginx/unit/issues/594

[ac000]

Do these kinds of things work with this patch?

Yes.

OK, could you also provide such an example in the commit message? Even if it's just this one

{
    "access_log": {
        "if": "$cookie_session",
        "path": "…"
    }
}

[bobr-mike]

Do these kinds of things work with this patch?

Yes.

OK, could you also provide such an example in the commit message? Even if it's just this one

{
    "access_log": {
        "if": "$cookie_session",
        "path": "…"
    }
}

I did and got: { "error": "Invalid configuration.", "detail": "Unknown parameter \"if\"." }

[hongzhidao]

Hi @bobr-mike Did you apply the PR?

[bobr-mike]

Hi @bobr-mike Did you apply the PR?

I think did not. Too hurry to post the message, sorry) Finding how to apply it.

[hongzhidao]

That's ok, thanks for testing :)

[andrey-zelenkov]

I am getting router crash while running test/test_access_log.py::test_access_log_partial with this patch on my local machine:

==15930==ERROR: AddressSanitizer: heap-use-after-free on address 0x00010690a280 at pc 0x000102e90b8c bp 0x00016d23ad20 sp 0x00016d23ad18
READ of size 8 at 0x00010690a280 thread T4
    #0 0x102e90b88 in nxt_router_access_log_write_ready nxt_router_access_log.c:211
    #1 0x102e35bb8 in nxt_event_engine_start nxt_event_engine.c:542
    #2 0x102e2cf08 in nxt_thread_trampoline nxt_thread.c:126
    #3 0x18133e030 in _pthread_start+0x84 (libsystem_pthread.dylib:arm64e+0x7030)
    #4 0x181338e38 in thread_start+0x4 (libsystem_pthread.dylib:arm64e+0x1e38)

0x00010690a280 is located 16 bytes inside of 64-byte region [0x00010690a270,0x00010690a2b0)
freed by thread T4 here:
    #0 0x103e77380 in wrap_free+0x98 (libclang_rt.asan_osx_dynamic.dylib:arm64e+0x53380)
    #1 0x102e196f0 in nxt_mp_destroy nxt_mp.c:342
    #2 0x102e9f794 in nxt_http_request_close_handler nxt_http_request.c:860
    #3 0x102e35bb8 in nxt_event_engine_start nxt_event_engine.c:542
    #4 0x102e2cf08 in nxt_thread_trampoline nxt_thread.c:126
    #5 0x18133e030 in _pthread_start+0x84 (libsystem_pthread.dylib:arm64e+0x7030)
    #6 0x181338e38 in thread_start+0x4 (libsystem_pthread.dylib:arm64e+0x1e38)

previously allocated by thread T4 here:
    #0 0x103e779a8 in wrap_posix_memalign+0xa4 (libclang_rt.asan_osx_dynamic.dylib:arm64e+0x539a8)
    #1 0x102df4424 in nxt_memalign nxt_malloc.c:134
    #2 0x102e19b1c in nxt_mp_alloc_large nxt_mp.c:743
    #3 0x102e8fe64 in nxt_router_access_log_writer nxt_router_access_log.c:173
    #4 0x102e9f5f0 in nxt_http_request_close_handler nxt_http_request.c:833
    #5 0x102e35bb8 in nxt_event_engine_start nxt_event_engine.c:542
    #6 0x102e2cf08 in nxt_thread_trampoline nxt_thread.c:126
    #7 0x18133e030 in _pthread_start+0x84 (libsystem_pthread.dylib:arm64e+0x7030)
    #8 0x181338e38 in thread_start+0x4 (libsystem_pthread.dylib:arm64e+0x1e38)

Thread T4 created by T0 here:
    #0 0x103e701b0 in wrap_pthread_create+0x54 (libclang_rt.asan_osx_dynamic.dylib:arm64e+0x4c1b0)
    #1 0x102e2cb80 in nxt_thread_create nxt_thread.c:85
    #2 0x102e726cc in nxt_router_conf_apply nxt_router.c:1261
    #3 0x102e81fac in nxt_router_conf_data_handler nxt_router.c:819
    #4 0x102e09254 in nxt_port_read_msg_process nxt_port_socket.c:1271
    #5 0x102e08850 in nxt_port_read_handler nxt_port_socket.c:778
    #6 0x102e35bb8 in nxt_event_engine_start nxt_event_engine.c:542
    #7 0x102df2814 in main nxt_main.c:35
    #8 0x180fbd0dc  (<unknown module>)

SUMMARY: AddressSanitizer: heap-use-after-free nxt_router_access_log.c:211 in nxt_router_access_log_write_ready
Shadow bytes around the buggy address:
  0x00010690a000: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
  0x00010690a080: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
  0x00010690a100: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
  0x00010690a180: fa fa fd fd fd fd fd fd fd fd fa fa fa fa fa fa
  0x00010690a200: fd fd fd fd fd fd fd fd fa fa fa fa fa fa fd fd
=>0x00010690a280:[fd]fd fd fd fd fd fa fa fa fa fa fa fa fa fa fa
  0x00010690a300: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
  0x00010690a380: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
  0x00010690a400: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
  0x00010690a480: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
  0x00010690a500: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
Shadow byte legend (one shadow byte represents 8 application bytes):
  Addressable:           00
  Partially addressable: 01 02 03 04 05 06 07 
  Heap left redzone:       fa
  Freed heap region:       fd
  Stack left redzone:      f1
  Stack mid redzone:       f2
  Stack right redzone:     f3
  Stack after return:      f5
  Stack use after scope:   f8
  Global redzone:          f9
  Global init order:       f6
  Poisoned by user:        f7
  Container overflow:      fc
  Array cookie:            ac
  Intra object redzone:    bb
  ASan internal:           fe
  Left alloca redzone:     ca
  Right alloca redzone:    cb
==15930==ABORTING

configured as ./configure --debug --openssl --njs --cc-opt='-I/opt/homebrew/Cellar/openssl@1.1/1.1.1w/include -I../njs/src -I../njs/build -DNXT_DEBUG_MEMORY=1 -fsanitize=address' --ld-opt='-L/opt/homebrew/Cellar/openssl@1.1/1.1.1w/lib -L../njs/build -fsanitize=address'

Please ping me if you need more info.

[andrey-zelenkov]

And one more problem with test/test_access_log.py::test_access_log_format:

AddressSanitizer:DEADLYSIGNAL
=================================================================
==3390066==ERROR: AddressSanitizer: SEGV on unknown address 0x000000000239 (pc 0x55cdcf3f9abc bp 0x61200000ff40 sp 0x7f98db1f4810 T2)
==3390066==The signal is caused by a READ memory access.
==3390066==Hint: address points to the zero page.
    #0 0x55cdcf3f9abc in nxt_h1p_request_close src/nxt_h1proto.c:1703
    #1 0x55cdcf3fcf7a in nxt_http_request_close_handler src/nxt_http_request.c:858
    #2 0x55cdcf3da3cc in nxt_router_http_request_done src/nxt_router.c:5234
    #3 0x55cdcf3b6545 in nxt_event_engine_start src/nxt_event_engine.c:542
    #4 0x55cdcf3d6af2 in nxt_router_thread_start src/nxt_router.c:3645
    #5 0x55cdcf3b0981 in nxt_thread_trampoline src/nxt_thread.c:126
    #6 0x7f98de28f189  (/lib/x86_64-linux-gnu/libc.so.6+0x8f189) (BuildId: bdb8aa3b1b60f9d43e1c70ba98158e05f765efdc)
    #7 0x7f98de31dbcf  (/lib/x86_64-linux-gnu/libc.so.6+0x11dbcf) (BuildId: bdb8aa3b1b60f9d43e1c70ba98158e05f765efdc)

AddressSanitizer can not provide additional info.
SUMMARY: AddressSanitizer: SEGV src/nxt_h1proto.c:1703 in nxt_h1p_request_close
Thread T2 created by T0 here:
    #0 0x7f98dec49185 in __interceptor_pthread_create ../../../../src/libsanitizer/asan/asan_interceptors.cpp:208
    #1 0x55cdcf3b0490 in nxt_thread_create src/nxt_thread.c:85

==3390066==ABORTING

configured as ./configure --debug --openssl --cc-opt='-I/opt/homebrew/Cellar/openssl@1.1/1.1.1w/include -I../njs/src -I../njs/build -DNXT_DEBUG_MEMORY=1 -fsanitize=address' --ld-opt='-L/opt/homebrew/Cellar/openssl@1.1/1.1.1w/lib -L../njs/build -fsanitize=address'

[hongzhidao]

Generally, personally, I would do a patch or patches that adds the core feature then another patch that hooks it up to the config system.

But it's a relatively small patch, so I'll leave that up to you...

Good suggestion, it makes sense to split it into two commits. Btw, welcome to review again.

[hongzhidao]

Hi @andrey-zelenkov

Please ping me if you need more info.

Fixed, thanks.

[ac000]

Hi Zhidao,

Perhaps you could fix the alignment of the JSON snippets in the commit message for consistency and to show the preferred way of formatting the conditional expression.

For instance, Liam's examples look like

{
  "access_log": {
    "if": "`${uri == '/health' ? false : true}`",
    "path": "…"
}

With the if and path slightly indented...

[hongzhidao]

Sure, my mistake. I copied it from GH and it looks fine in vim. I'll check it again after pushing to GH, still getting used to GH.

[hongzhidao]

Changes:

Fixed the issue found by tests.