Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

long_body - tests fail #1659

Closed
pale-emperor opened this issue Jul 12, 2022 · 3 comments
Closed

long_body - tests fail #1659

pale-emperor opened this issue Jul 12, 2022 · 3 comments
Assignees
@const-t
Labels
bug h2 http/1.1
Milestone
0.7 - HTTP/2

Comments

@pale-emperor
Copy link
Contributor

pale-emperor commented Jul 12, 2022 •
edited
Loading

Long body have 4 tests which leads to FAIL condition:

long_body.test_long_request.RequestTest1M
long_body.test_long_request.RequestTest1k

[12199.646174] [tempesta fw] Warning: Parser error: state=RGen_BodyInit input(-8)=0xa('0.0.1
[12199.646175] [tempesta fw] Warning: failed to parse request: 127.0.0.1

Tests:

long_body.test_long_response.ResponseTest1k
long_body.test_long_response.ResponseTest1M

Also was disabled by another issue

I think we have a problems with tempesta-fw parser which leads to test fails
@pale-emperor
Copy link
Contributor Author

pale-emperor commented Jul 12, 2022 •
edited
Loading

long_body.test_long_request.RequestTest1M.test DMESG:


[ 3837.795960] Start test: long_body.test_long_request.RequestTest1M.test
[ 3837.840503] [tdb] Start Tempesta DB
[ 3837.853926] net_ratelimit: 7086 callbacks suppressed
[ 3837.853927] [tempesta fw] Initializing Tempesta FW kernel module...
[ 3837.898319] [tempesta fw] Configuration processing is completed.
[ 3837.918958] [tdb] Opened table /opt/tempesta/db/filter0.tdb: size=16777216 rec_size=20 base=000000003d9ef670
[ 3837.924261] [tdb] Opened table /opt/tempesta/db/sessions0.tdb: size=16777216 rec_size=312 base=00000000ef3b3cae
[ 3837.929071] [tdb] Opened table /opt/tempesta/db/client0.tdb: size=16777216 rec_size=624 base=00000000a01aa6dc
[ 3837.946265] [tempesta fw] Open listen socket on: 0.0.0.0
[ 3837.961763] [tempesta fw] Tempesta FW is ready
[ 3837.988830] [tempesta fw] Warning: tfw_http_parse_check_bodyless_meth: Content-Length or Content-Type not allowed to be used with such (overridden) method
[ 3837.989238] [tempesta fw] Warning: Parser error: state=RGen_BodyInit input(-8)=0xa('48576
               
               xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx') data_len=32741 off=59
[ 3837.989850] [tempesta fw] Warning: failed to parse request: 127.0.0.1
[ 3837.990231] [tempesta fw] Warning: tfw_http_parse_check_bodyless_meth: Content-Length or Content-Type not allowed to be used with such (overridden) method
[ 3837.990629] [tempesta fw] Warning: Parser error: state=RGen_BodyInit input(-8)=0xa('48576
               
               xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx') data_len=32741 off=59
[ 3837.991245] [tempesta fw] Warning: failed to parse request: 127.0.0.1
[ 3837.991539] [tempesta fw] Warning: tfw_http_parse_check_bodyless_meth: Content-Length or Content-Type not allowed to be used with such (overridden) method
[ 3842.854409] net_ratelimit: 182352 callbacks suppressed
[ 3842.854410] [tempesta fw] Warning: tfw_http_parse_check_bodyless_meth: Content-Length or Content-Type not allowed to be used with such (overridden) method
[ 3842.854702] [tempesta fw] Warning: tfw_http_parse_check_bodyless_meth: Content-Length or Content-Type not allowed to be used with such (overridden) method
[ 3842.854715] [tempesta fw] Warning: Parser error: state=RGen_BodyInit input(-8)=0xa('48576
               
               xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx') data_len=29156 off=59
[ 3842.855209] [tempesta fw] Warning: Parser error: state=RGen_BodyInit input(-8)=0xa('0.0.1
               
               xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx') data_len=30356 off=59
[ 3842.855210] [tempesta fw] Warning: failed to parse request: 127.0.0.1
[ 3842.855319] [tempesta fw] Warning: tfw_http_parse_check_bodyless_meth: Content-Length or Content-Type not allowed to be used with such (overridden) method
[ 3842.855727] [tempesta fw] Warning: failed to parse request: 127.0.0.1
[ 3842.856494] [tempesta fw] Warning: Parser error: state=RGen_BodyInit input(-8)=0xa('0.0.1
               
               xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx') data_len=30296 off=59
[ 3842.857369] [tempesta fw] Warning: tfw_http_parse_check_bodyless_meth: Content-Length or Content-Type not allowed to be used with such (overridden) method
[ 3842.857518] [tempesta fw] Warning: failed to parse request: 127.0.0.1
[ 3847.858107] net_ratelimit: 184609 callbacks suppressed
[ 3847.858108] [tempesta fw] Warning: tfw_http_parse_check_bodyless_meth: Content-Length or Content-Type not allowed to be used with such (overridden) method
[ 3847.858342] [tempesta fw] Warning: tfw_http_parse_check_bodyless_meth: Content-Length or Content-Type not allowed to be used with such (overridden) method
[ 3847.858393] [tempesta fw] Warning: Parser error: state=RGen_BodyInit input(-8)=0xa('48576
               
               xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx') data_len=25676 off=59
[ 3847.858394] [tempesta fw] Warning: failed to parse request: 127.0.0.1
[ 3847.858515] [tempesta fw] Warning: tfw_http_parse_check_bodyless_meth: Content-Length or Content-Type not allowed to be used with such (overridden) method
[ 3847.858897] [tempesta fw] Warning: Parser error: state=RGen_BodyInit input(-8)=0xa('0.0.1
               
               xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx') data_len=10076 off=59
[ 3847.859372] [tempesta fw] Warning: Parser error: state=RGen_BodyInit input(-8)=0xa('48576
               
               xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx') data_len=25616 off=59
[ 3847.860085] [tempesta fw] Warning: failed to parse request: 127.0.0.1
[ 3847.860344] [tempesta fw] Warning: failed to parse request: 127.0.0.1
[ 3847.860959] [tempesta fw] Warning: tfw_http_parse_check_bodyless_meth: Content-Length or Content-Type not allowed to be used with such (overridden) method
[ 3848.165230] [tdb] Close table 'client0.tdb'
[ 3848.168839] [tdb] Close table 'sessions0.tdb'
[ 3848.201354] [tdb] Close table 'filter0.tdb'
[ 3848.222768] [tempesta fw] exiting...
[ 3848.293565] =============================================================================
[ 3848.293888] BUG tfw_stream_cache (Tainted: G    B   W  OE    ): Objects remaining in tfw_stream_cache on __kmem_cache_shutdown()
[ 3848.294521] -----------------------------------------------------------------------------

[ 3848.295118] INFO: Slab 0x00000000036a03f4 objects=46 used=3 fp=0x00000000471a34d9 flags=0xfffffc0010200
[ 3848.295628] CPU: 1 PID: 26025 Comm: rmmod Tainted: G    B   W  OE     5.10.35+ tempesta-tech/tempesta-test#1
[ 3848.295941] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 11/12/2020
[ 3848.296491] Call Trace:
[ 3848.296763]  dump_stack+0x74/0x92
[ 3848.297015]  slab_err+0xb7/0xdc
[ 3848.297272]  ? slub_cpu_dead+0xb0/0xb0
[ 3848.297511]  ? kernel_poison_pages+0xc0/0xc0
[ 3848.297757]  ? on_each_cpu_cond_mask+0x48/0x90
[ 3848.297986]  __kmem_cache_shutdown.cold+0x3b/0x131
[ 3848.298226]  kmem_cache_destroy+0x59/0x100
[ 3848.298458]  tfw_h2_stream_cache_destroy+0x15/0x20 [tempesta_fw]
[ 3848.298700]  tfw_h2_cleanup+0xe/0x10 [tempesta_fw]
[ 3848.298930]  tfw_tls_exit+0x24/0x40 [tempesta_fw]
[ 3848.299212]  tfw_exit+0xc6/0xd9 [tempesta_fw]
[ 3848.299482]  __x64_sys_delete_module+0x146/0x2a0
[ 3848.299759]  do_syscall_64+0x38/0x90
[ 3848.299993]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 3848.300210] RIP: 0033:0x7fddff0dfa6b
[ 3848.300412] 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
[ 3848.301057] RSP: 002b:00007fff08940ce8 EFLAGS: 00000206 ORIG_RAX: 00000000000000b0
[ 3848.301270] RAX: ffffffffffffffda RBX: 00005628b0450750 RCX: 00007fddff0dfa6b
[ 3848.301475] RDX: 000000000000000a RSI: 0000000000000800 RDI: 00005628b04507b8
[ 3848.301690] RBP: 00007fff08940d48 R08: 0000000000000000 R09: 0000000000000000
[ 3848.301892] R10: 00007fddff15bac0 R11: 0000000000000206 R12: 00007fff08940f20
[ 3848.302104] R13: 00007fff08942822 R14: 00005628b04502a0 R15: 00005628b0450750
[ 3848.302316] INFO: Object 0x0000000054117461 @offset=11968
[ 3848.302523] INFO: Object 0x0000000090380c17 @offset=18304
[ 3848.302735] INFO: Object 0x00000000f6ae3833 @offset=29568
[ 3848.302931] =============================================================================
[ 3848.303138] BUG tfw_stream_cache (Tainted: G    B   W  OE    ): Objects remaining in tfw_stream_cache on __kmem_cache_shutdown()
[ 3848.303530] -----------------------------------------------------------------------------

[ 3848.303930] INFO: Slab 0x000000005eff60d2 objects=46 used=1 fp=0x00000000986c5acc flags=0xfffffc0010200
[ 3848.304331] CPU: 1 PID: 26025 Comm: rmmod Tainted: G    B   W  OE     5.10.35+ tempesta-tech/tempesta-test#1
[ 3848.304527] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 11/12/2020
[ 3848.304942] Call Trace:
[ 3848.305156]  dump_stack+0x74/0x92
[ 3848.305362]  slab_err+0xb7/0xdc
[ 3848.305579]  ? printk+0x58/0x6f
[ 3848.305784]  __kmem_cache_shutdown.cold+0x3b/0x131
[ 3848.305988]  kmem_cache_destroy+0x59/0x100
[ 3848.306207]  tfw_h2_stream_cache_destroy+0x15/0x20 [tempesta_fw]
[ 3848.306417]  tfw_h2_cleanup+0xe/0x10 [tempesta_fw]
[ 3848.306635]  tfw_tls_exit+0x24/0x40 [tempesta_fw]
[ 3848.306845]  tfw_exit+0xc6/0xd9 [tempesta_fw]
[ 3848.307057]  __x64_sys_delete_module+0x146/0x2a0
[ 3848.307265]  do_syscall_64+0x38/0x90
[ 3848.307468]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 3848.307684] RIP: 0033:0x7fddff0dfa6b
[ 3848.307887] 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
[ 3848.308513] RSP: 002b:00007fff08940ce8 EFLAGS: 00000206 ORIG_RAX: 00000000000000b0
[ 3848.308730] RAX: ffffffffffffffda RBX: 00005628b0450750 RCX: 00007fddff0dfa6b
[ 3848.308936] RDX: 000000000000000a RSI: 0000000000000800 RDI: 00005628b04507b8
[ 3848.309151] RBP: 00007fff08940d48 R08: 0000000000000000 R09: 0000000000000000
[ 3848.309358] R10: 00007fddff15bac0 R11: 0000000000000206 R12: 00007fff08940f20
[ 3848.309572] R13: 00007fff08942822 R14: 00005628b04502a0 R15: 00005628b0450750
[ 3848.309785] INFO: Object 0x00000000105b3421 @offset=13376
[ 3848.310007] kmem_cache_destroy tfw_stream_cache: Slab cache still has objects
[ 3848.310227] CPU: 1 PID: 26025 Comm: rmmod Tainted: G    B   W  OE     5.10.35+ tempesta-tech/tempesta-test#1
[ 3848.310443] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 11/12/2020
[ 3848.310881] Call Trace:
[ 3848.311100]  dump_stack+0x74/0x92
[ 3848.311310]  kmem_cache_destroy.cold+0x16/0x1b
[ 3848.311519]  tfw_h2_stream_cache_destroy+0x15/0x20 [tempesta_fw]
[ 3848.311738]  tfw_h2_cleanup+0xe/0x10 [tempesta_fw]
[ 3848.311939]  tfw_tls_exit+0x24/0x40 [tempesta_fw]
[ 3848.312147]  tfw_exit+0xc6/0xd9 [tempesta_fw]
[ 3848.312340]  __x64_sys_delete_module+0x146/0x2a0
[ 3848.312524]  do_syscall_64+0x38/0x90
[ 3848.312719]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 3848.312906] RIP: 0033:0x7fddff0dfa6b
[ 3848.313096] 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
[ 3848.313691] RSP: 002b:00007fff08940ce8 EFLAGS: 00000206 ORIG_RAX: 00000000000000b0
[ 3848.313896] RAX: ffffffffffffffda RBX: 00005628b0450750 RCX: 00007fddff0dfa6b
[ 3848.314125] RDX: 000000000000000a RSI: 0000000000000800 RDI: 00005628b04507b8
[ 3848.314337] RBP: 00007fff08940d48 R08: 0000000000000000 R09: 0000000000000000
[ 3848.314547] R10: 00007fddff15bac0 R11: 0000000000000206 R12: 00007fff08940f20
[ 3848.314767] R13: 00007fff08942822 R14: 00005628b04502a0 R15: 00005628b0450750
[ 3848.331431] [tdb] Shutdown Tempesta DB
[ 3848.402454] End test:   long_body.test_long_request.RequestTest1M.test

@pale-emperor pale-emperor transferred this issue from tempesta-tech/tempesta-test Jul 12, 2022
@krizhanovsky krizhanovsky reopened this Jul 12, 2022
@krizhanovsky krizhanovsky self-assigned this Jul 12, 2022
@krizhanovsky
Copy link
Contributor

Objects remaining issue is gone in #1643, but the parser errors are still with us.

@krizhanovsky krizhanovsky removed their assignment Aug 18, 2022
@const-t
Copy link
Contributor

const-t commented Nov 8, 2022

Current tests completely reworked in tempesta-tech/tempesta-test#304. Logging issue was fixed in PR #1418

@const-t const-t closed this as completed Nov 8, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@const-t const-t

Labels
bug h2 http/1.1
Projects
None yet
Milestone
0.7 - HTTP/2
Development

No branches or pull requests
3 participants
@krizhanovsky @const-t @pale-emperor