search

tempesta-tech / tempesta-test

Test suite for Tempesta FW
11 stars 4 forks source link

test ALPN protocol priority order #283

Closed nickzaev closed 2 years ago

nickzaev commented 2 years ago

Add tests to ensure that a proper protocol gets picked up after ALPN.

nickzaev commented 2 years ago

Currently those 2 tests fail with dmesg:

[Tue Aug 16 15:16:31 2022] Start test: tls.test_alpn_order.TestALPNOrderH1.test                                                                                                                                                                       
[Tue Aug 16 15:16:31 2022] [tdb] Start Tempesta DB
[Tue Aug 16 15:16:32 2022] [tempesta fw] Initializing Tempesta FW kernel module...
[Tue Aug 16 15:16:32 2022] [tempesta fw] Configuration processing is completed.
[Tue Aug 16 15:16:32 2022] [tdb] Opened table /opt/tempesta/db/filter0.tdb: size=16777216 rec_size=20 base=00000000137a822a
[Tue Aug 16 15:16:32 2022] [tdb] Opened table /opt/tempesta/db/cache0.tdb: size=268435456 rec_size=0 base=00000000074f163f
[Tue Aug 16 15:16:32 2022] [tdb] Opened table /opt/tempesta/db/sessions0.tdb: size=16777216 rec_size=312 base=000000001c2e2115
[Tue Aug 16 15:16:32 2022] [tdb] Opened table /opt/tempesta/db/client0.tdb: size=16777216 rec_size=624 base=000000008c73f762
[Tue Aug 16 15:16:32 2022] [tempesta fw] Open listen socket on: 0.0.0.0
[Tue Aug 16 15:16:32 2022] [tempesta fw] Tempesta FW is ready
[Tue Aug 16 15:16:32 2022] [tdb] Close table 'client0.tdb'
[Tue Aug 16 15:16:32 2022] [tdb] Close table 'sessions0.tdb'
[Tue Aug 16 15:16:32 2022] [tdb] Close table 'cache0.tdb'
[Tue Aug 16 15:16:32 2022] [tdb] Close table 'filter0.tdb'
[Tue Aug 16 15:16:32 2022] [tempesta fw] modules are stopped
[Tue Aug 16 15:16:32 2022] [tempesta fw] exiting...
[Tue Aug 16 15:16:32 2022] =============================================================================
[Tue Aug 16 15:16:32 2022] BUG tfw_stream_cache (Tainted: G    B   W  OE    ): Objects remaining in tfw_stream_cache on __kmem_cache_shutdown()
[Tue Aug 16 15:16:32 2022] -----------------------------------------------------------------------------

[Tue Aug 16 15:16:32 2022] INFO: Slab 0x00000000868d39fa objects=23 used=1 fp=0x0000000012c5821a flags=0xfffffc0010200
[Tue Aug 16 15:16:32 2022] CPU: 1 PID: 297742 Comm: rmmod Tainted: G    B   W  OE     5.10.35+ #1
[Tue Aug 16 15:16:32 2022] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.15.0-0-g2dd4b9b3f840-prebuilt.qemu.org 04/01/2014
[Tue Aug 16 15:16:32 2022] Call Trace:
[Tue Aug 16 15:16:32 2022]  dump_stack+0x74/0x92
[Tue Aug 16 15:16:32 2022]  slab_err+0xb7/0xdc
[Tue Aug 16 15:16:32 2022]  ? slub_cpu_dead+0xb0/0xb0
[Tue Aug 16 15:16:32 2022]  ? kernel_poison_pages+0xc0/0xc0
[Tue Aug 16 15:16:32 2022]  ? on_each_cpu_cond_mask+0x48/0x90
[Tue Aug 16 15:16:32 2022]  __kmem_cache_shutdown.cold+0x3b/0x131
[Tue Aug 16 15:16:32 2022]  kmem_cache_destroy+0x59/0x100
[Tue Aug 16 15:16:32 2022]  tfw_h2_stream_cache_destroy+0x15/0x20 [tempesta_fw]
[Tue Aug 16 15:16:32 2022]  tfw_h2_cleanup+0xe/0x10 [tempesta_fw]
[Tue Aug 16 15:16:32 2022]  tfw_tls_exit+0x24/0x40 [tempesta_fw]
[Tue Aug 16 15:16:32 2022]  tfw_exit+0xc6/0xd9 [tempesta_fw]
[Tue Aug 16 15:16:32 2022]  __x64_sys_delete_module+0x146/0x2a0
[Tue Aug 16 15:16:32 2022]  do_syscall_64+0x38/0x90
[Tue Aug 16 15:16:32 2022]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[Tue Aug 16 15:16:32 2022] RIP: 0033:0x7fe7b729fa6b
[Tue Aug 16 15:16:32 2022] Code: 73 01 c3 48 8b 0d 25 c4 0c 00 f7 d8 64 89 01 48 83 c8 ff c3 66 2e 0f 1f 84 00 00 00 00 00 90 f3 0f 1e fa b8 b0 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d f5 c3 0c 00 f7 d8 64 89 01 48
[Tue Aug 16 15:16:32 2022] RSP: 002b:00007ffee6f97d08 EFLAGS: 00000206 ORIG_RAX: 00000000000000b0
[Tue Aug 16 15:16:32 2022] RAX: ffffffffffffffda RBX: 000055c8d0a4f750 RCX: 00007fe7b729fa6b
[Tue Aug 16 15:16:32 2022] RDX: 000000000000000a RSI: 0000000000000800 RDI: 000055c8d0a4f7b8
[Tue Aug 16 15:16:32 2022] RBP: 00007ffee6f97d68 R08: 0000000000000000 R09: 0000000000000000
[Tue Aug 16 15:16:32 2022] R10: 00007fe7b731bac0 R11: 0000000000000206 R12: 00007ffee6f97f40
[Tue Aug 16 15:16:32 2022] R13: 00007ffee6f9832a R14: 000055c8d0a4f2a0 R15: 000055c8d0a4f750
[Tue Aug 16 15:16:32 2022] INFO: Object 0x00000000f745079c @offset=11968
[Tue Aug 16 15:16:32 2022] kmem_cache_destroy tfw_stream_cache: Slab cache still has objects
[Tue Aug 16 15:16:32 2022] CPU: 1 PID: 297742 Comm: rmmod Tainted: G    B   W  OE     5.10.35+ #1
[Tue Aug 16 15:16:32 2022] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.15.0-0-g2dd4b9b3f840-prebuilt.qemu.org 04/01/2014
[Tue Aug 16 15:16:32 2022] Call Trace:
[Tue Aug 16 15:16:32 2022]  dump_stack+0x74/0x92
[Tue Aug 16 15:16:32 2022]  kmem_cache_destroy.cold+0x16/0x1b
[Tue Aug 16 15:16:32 2022]  tfw_h2_stream_cache_destroy+0x15/0x20 [tempesta_fw]
[Tue Aug 16 15:16:32 2022]  tfw_h2_cleanup+0xe/0x10 [tempesta_fw]
[Tue Aug 16 15:16:32 2022]  tfw_tls_exit+0x24/0x40 [tempesta_fw]
[Tue Aug 16 15:16:32 2022]  tfw_exit+0xc6/0xd9 [tempesta_fw]
[Tue Aug 16 15:16:32 2022]  __x64_sys_delete_module+0x146/0x2a0
[Tue Aug 16 15:16:32 2022]  do_syscall_64+0x38/0x90
[Tue Aug 16 15:16:32 2022]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[Tue Aug 16 15:16:32 2022] RIP: 0033:0x7fe7b729fa6b
[Tue Aug 16 15:16:32 2022] Code: 73 01 c3 48 8b 0d 25 c4 0c 00 f7 d8 64 89 01 48 83 c8 ff c3 66 2e 0f 1f 84 00 00 00 00 00 90 f3 0f 1e fa b8 b0 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d f5 c3 0c 00 f7 d8 64 89 01 48
[Tue Aug 16 15:16:32 2022] RSP: 002b:00007ffee6f97d08 EFLAGS: 00000206 ORIG_RAX: 00000000000000b0
[Tue Aug 16 15:16:32 2022] RAX: ffffffffffffffda RBX: 000055c8d0a4f750 RCX: 00007fe7b729fa6b
[Tue Aug 16 15:16:32 2022] RDX: 000000000000000a RSI: 0000000000000800 RDI: 000055c8d0a4f7b8
[Tue Aug 16 15:16:32 2022] RBP: 00007ffee6f97d68 R08: 0000000000000000 R09: 0000000000000000
[Tue Aug 16 15:16:32 2022] R10: 00007fe7b731bac0 R11: 0000000000000206 R12: 00007ffee6f97f40
[Tue Aug 16 15:16:32 2022] R13: 00007ffee6f9832a R14: 000055c8d0a4f2a0 R15: 000055c8d0a4f750
[Tue Aug 16 15:16:33 2022] [tdb] Shutdown Tempesta DB
[Tue Aug 16 15:16:33 2022] End test:   tls.test_alpn_order.TestALPNOrderH1.test
[Tue Aug 16 15:16:33 2022] Start test: tls.test_alpn_order.TestALPNOrderH2.test
[Tue Aug 16 15:16:33 2022] [tdb] Start Tempesta DB
[Tue Aug 16 15:16:33 2022] [tempesta fw] Initializing Tempesta FW kernel module...
[Tue Aug 16 15:16:33 2022] [tempesta fw] Configuration processing is completed.
[Tue Aug 16 15:16:33 2022] [tdb] Opened table /opt/tempesta/db/filter0.tdb: size=16777216 rec_size=20 base=00000000137a822a
[Tue Aug 16 15:16:33 2022] [tdb] Opened table /opt/tempesta/db/cache0.tdb: size=268435456 rec_size=0 base=00000000074f163f
[Tue Aug 16 15:16:33 2022] [tdb] Opened table /opt/tempesta/db/sessions0.tdb: size=16777216 rec_size=312 base=000000001c2e2115
[Tue Aug 16 15:16:33 2022] [tdb] Opened table /opt/tempesta/db/client0.tdb: size=16777216 rec_size=624 base=000000008c73f762
[Tue Aug 16 15:16:33 2022] [tempesta fw] Open listen socket on: 0.0.0.0
[Tue Aug 16 15:16:33 2022] [tempesta fw] Tempesta FW is ready
[Tue Aug 16 15:16:33 2022] [tdb] Close table 'client0.tdb'
[Tue Aug 16 15:16:33 2022] [tdb] Close table 'sessions0.tdb'
[Tue Aug 16 15:16:33 2022] [tdb] Close table 'cache0.tdb'
[Tue Aug 16 15:16:33 2022] [tdb] Close table 'filter0.tdb'
[Tue Aug 16 15:16:33 2022] [tempesta fw] modules are stopped
[Tue Aug 16 15:16:33 2022] [tempesta fw] exiting...
[Tue Aug 16 15:16:34 2022] =============================================================================
[Tue Aug 16 15:16:34 2022] BUG tfw_stream_cache (Tainted: G    B   W  OE    ): Objects remaining in tfw_stream_cache on __kmem_cache_shutdown()
[Tue Aug 16 15:16:34 2022] -----------------------------------------------------------------------------

[Tue Aug 16 15:16:34 2022] INFO: Slab 0x00000000868d39fa objects=23 used=1 fp=0x0000000012c5821a flags=0xfffffc0010200
[Tue Aug 16 15:16:34 2022] CPU: 1 PID: 297861 Comm: rmmod Tainted: G    B   W  OE     5.10.35+ #1
[Tue Aug 16 15:16:34 2022] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.15.0-0-g2dd4b9b3f840-prebuilt.qemu.org 04/01/2014
[Tue Aug 16 15:16:34 2022] Call Trace:
[Tue Aug 16 15:16:34 2022]  dump_stack+0x74/0x92
[Tue Aug 16 15:16:34 2022]  slab_err+0xb7/0xdc
[Tue Aug 16 15:16:34 2022]  ? slub_cpu_dead+0xb0/0xb0
[Tue Aug 16 15:16:34 2022]  ? kernel_poison_pages+0xc0/0xc0
[Tue Aug 16 15:16:34 2022]  ? on_each_cpu_cond_mask+0x48/0x90
[Tue Aug 16 15:16:34 2022]  __kmem_cache_shutdown.cold+0x3b/0x131
[Tue Aug 16 15:16:34 2022]  kmem_cache_destroy+0x59/0x100
[Tue Aug 16 15:16:34 2022]  tfw_h2_stream_cache_destroy+0x15/0x20 [tempesta_fw]
[Tue Aug 16 15:16:34 2022]  tfw_h2_cleanup+0xe/0x10 [tempesta_fw]
[Tue Aug 16 15:16:34 2022]  tfw_tls_exit+0x24/0x40 [tempesta_fw]
[Tue Aug 16 15:16:34 2022]  tfw_exit+0xc6/0xd9 [tempesta_fw]
[Tue Aug 16 15:16:34 2022]  __x64_sys_delete_module+0x146/0x2a0
[Tue Aug 16 15:16:34 2022]  do_syscall_64+0x38/0x90
[Tue Aug 16 15:16:34 2022]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[Tue Aug 16 15:16:34 2022] RIP: 0033:0x7fabcb067a6b
[Tue Aug 16 15:16:34 2022] Code: 73 01 c3 48 8b 0d 25 c4 0c 00 f7 d8 64 89 01 48 83 c8 ff c3 66 2e 0f 1f 84 00 00 00 00 00 90 f3 0f 1e fa b8 b0 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d f5 c3 0c 00 f7 d8 64 89 01 48
[Tue Aug 16 15:16:34 2022] RSP: 002b:00007ffcb352c848 EFLAGS: 00000206 ORIG_RAX: 00000000000000b0
[Tue Aug 16 15:16:34 2022] RAX: ffffffffffffffda RBX: 0000564d63152750 RCX: 00007fabcb067a6b
[Tue Aug 16 15:16:34 2022] RDX: 000000000000000a RSI: 0000000000000800 RDI: 0000564d631527b8
[Tue Aug 16 15:16:34 2022] RBP: 00007ffcb352c8a8 R08: 0000000000000000 R09: 0000000000000000
[Tue Aug 16 15:16:34 2022] R10: 00007fabcb0e3ac0 R11: 0000000000000206 R12: 00007ffcb352ca80
[Tue Aug 16 15:16:34 2022] R13: 00007ffcb352e32a R14: 0000564d631522a0 R15: 0000564d63152750
[Tue Aug 16 15:16:34 2022] INFO: Object 0x00000000f745079c @offset=11968
[Tue Aug 16 15:16:34 2022] kmem_cache_destroy tfw_stream_cache: Slab cache still has objects
[Tue Aug 16 15:16:34 2022] CPU: 1 PID: 297861 Comm: rmmod Tainted: G    B   W  OE     5.10.35+ #1
[Tue Aug 16 15:16:34 2022] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.15.0-0-g2dd4b9b3f840-prebuilt.qemu.org 04/01/2014
[Tue Aug 16 15:16:34 2022] Call Trace:
[Tue Aug 16 15:16:34 2022]  dump_stack+0x74/0x92
[Tue Aug 16 15:16:34 2022]  kmem_cache_destroy.cold+0x16/0x1b
[Tue Aug 16 15:16:34 2022]  tfw_h2_stream_cache_destroy+0x15/0x20 [tempesta_fw]
[Tue Aug 16 15:16:34 2022]  tfw_h2_cleanup+0xe/0x10 [tempesta_fw]
[Tue Aug 16 15:16:34 2022]  tfw_tls_exit+0x24/0x40 [tempesta_fw]
[Tue Aug 16 15:16:34 2022]  tfw_exit+0xc6/0xd9 [tempesta_fw]
[Tue Aug 16 15:16:34 2022]  __x64_sys_delete_module+0x146/0x2a0
[Tue Aug 16 15:16:34 2022]  do_syscall_64+0x38/0x90
[Tue Aug 16 15:16:34 2022]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[Tue Aug 16 15:16:34 2022] RIP: 0033:0x7fabcb067a6b
[Tue Aug 16 15:16:34 2022] Code: 73 01 c3 48 8b 0d 25 c4 0c 00 f7 d8 64 89 01 48 83 c8 ff c3 66 2e 0f 1f 84 00 00 00 00 00 90 f3 0f 1e fa b8 b0 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d f5 c3 0c 00 f7 d8 64 89 01 48
[Tue Aug 16 15:16:34 2022] RSP: 002b:00007ffcb352c848 EFLAGS: 00000206 ORIG_RAX: 00000000000000b0
[Tue Aug 16 15:16:34 2022] RAX: ffffffffffffffda RBX: 0000564d63152750 RCX: 00007fabcb067a6b
[Tue Aug 16 15:16:34 2022] RDX: 000000000000000a RSI: 0000000000000800 RDI: 0000564d631527b8
[Tue Aug 16 15:16:34 2022] RBP: 00007ffcb352c8a8 R08: 0000000000000000 R09: 0000000000000000
[Tue Aug 16 15:16:34 2022] R10: 00007fabcb0e3ac0 R11: 0000000000000206 R12: 00007ffcb352ca80
[Tue Aug 16 15:16:34 2022] R13: 00007ffcb352e32a R14: 0000564d631522a0 R15: 0000564d63152750
[Tue Aug 16 15:16:34 2022] [tdb] Shutdown Tempesta DB
[Tue Aug 16 15:16:34 2022] End test:   tls.test_alpn_order.TestALPNOrderH2.test

The testing framework log is:

test (tls.test_alpn_order.TestALPNOrderBase) ... skipped 'This is an abstract class'
test (tls.test_alpn_order.TestALPNOrderH1) ... ERROR
test (tls.test_alpn_order.TestALPNOrderH2) ... ERROR

======================================================================
ERROR: test (tls.test_alpn_order.TestALPNOrderH1)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/root/tempesta-test/tls/test_alpn_order.py", line 47, in test
    with socket.create_connection((hostname, 443)) as sock:
  File "/usr/lib/python3.8/socket.py", line 808, in create_connection
    raise err
  File "/usr/lib/python3.8/socket.py", line 796, in create_connection
    sock.connect(sa)
ConnectionRefusedError: [Errno 111] Connection refused

======================================================================
ERROR: test (tls.test_alpn_order.TestALPNOrderH2)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/root/tempesta-test/tls/test_alpn_order.py", line 47, in test
    with socket.create_connection((hostname, 443)) as sock:
  File "/usr/lib/python3.8/socket.py", line 808, in create_connection
    raise err
  File "/usr/lib/python3.8/socket.py", line 796, in create_connection
    sock.connect(sa)
ConnectionRefusedError: [Errno 111] Connection refused

----------------------------------------------------------------------
Ran 3 tests in 2.519s

FAILED (errors=2, skipped=1)

Am I doing something wrong with the config or connections or that is a bug?

krizhanovsky commented 2 years ago

Am I doing something wrong with the config or connections or that is a bug?

Nothing wrong, this is just another appearance of https://github.com/tempesta-tech/tempesta/issues/1377 , which already has the warning messages for tfw_stream_cache

nickzaev commented 2 years ago

Also I've noticed that in dmesg Tempesta says:

[Mon Aug 22 13:11:43 2022] [tempesta fw] Open listen socket on: 0.0.0.0

i.e. without specifying a port number. It actually binds to 80 for some reason:

tcp6       0      0 0.0.0.0:80              :::*                    LISTEN      0          0          -

If I use the same configuration and start Tempesta manually, I get:

[Mon Aug 22 13:17:09 2022] [tempesta fw] Open listen socket on: 0.0.0.0:443
krizhanovsky commented 2 years ago

By default Tempesta FW binds to port 80 https://github.com/tempesta-tech/tempesta-test/pull/283/files/322259aaf897538e6299e3b508ae341be21aa52d..f6af0f4e5fafd49ff83bd6072d6631154216193b , there is no sense to build to all possible ports.

nickzaev commented 2 years ago

Actually the correct ALPN protocol names are http/1.1 and h2.

nickzaev commented 2 years ago

By default Tempesta FW binds to port 80 https://github.com/tempesta-tech/tempesta-test/pull/283/files/322259aaf897538e6299e3b508ae341be21aa52d..f6af0f4e5fafd49ff83bd6072d6631154216193b , there is no sense to build to all possible ports.

There was an error in config generation that was causing Tempesta to start up with an empty config.

krizhanovsky commented 2 years ago

Actually the correct ALPN protocol names are http/1.1 and h2.

Yeah, you're right and we have the same in Tempesta FW code https://github.com/tempesta-tech/tempesta/blob/master/tls/ttls.h#L235