Warning: fw/cache.c:2073 tfw_cache_copy_resp()

[krizhanovsky]

Scenario

Deploy production (10.245.18.154) and staging (10.245.18.235) container (the 2nd production container isn't used) with the WP website (see https://github.com/tempesta-tech/tempesta-tech.com/pull/85) on a host system:

$ lxc list
+----------------------+---------+----------------------+-----------------------------------------------+-----------+-----------+
|         NAME         |  STATE  |         IPV4         |                     IPV6                      |   TYPE    | SNAPSHOTS |
+----------------------+---------+----------------------+-----------------------------------------------+-----------+-----------+
| tempesta-site-prod   | RUNNING | 10.245.18.154 (eth0) | fd42:5e77:95a2:2eae:216:3eff:fe3f:43c3 (eth0) | CONTAINER | 0         |
+----------------------+---------+----------------------+-----------------------------------------------+-----------+-----------+
| tempesta-site-prod-2 | RUNNING | 10.245.18.100 (eth0) | fd42:5e77:95a2:2eae:216:3eff:fe88:59e1 (eth0) | CONTAINER | 0         |
+----------------------+---------+----------------------+-----------------------------------------------+-----------+-----------+
| tempesta-site-stage  | RUNNING | 10.245.18.235 (eth0) | fd42:5e77:95a2:2eae:216:3eff:fef5:6632 (eth0) | CONTAINER | 0         |
+----------------------+---------+----------------------+-----------------------------------------------+-----------+-----------+

Deploy Tempesta FW as of ee2d801 master in a 2 CPU VM with config:

listen 80;
listen 443 proto=h2;

cache 2;
cache_fulfill * *;
cache_methods GET HEAD;
cache_purge;
# Allow purging from the containers (upstream), localhost (VM) and the host.
cache_purge_acl 192.168.100.1 10.245.18.154 127.0.0.1;

access_log on;

frang_limits {
        request_rate 200;
        http_method_override_allowed true;
        http_methods post put get;
}

block_action attack reply;
block_action error reply;

# Make WordPress to work over TLS.
# See https://tempesta-tech.com/knowledge-base/WordPress-tips-and-tricks/
req_hdr_add X-Forwarded-Proto "https";

resp_hdr_set Strict-Transport-Security "max-age=31536000; includeSubDomains";

tls_certificate /etc/tempesta/tfw-root.crt;
tls_certificate_key /etc/tempesta/tfw-root.key;

srv_group production {
        server 10.245.18.154  conns_n=2;
}

srv_group staging {
        server 10.245.18.235  conns_n=2;
}

vhost tempesta-tech.com {
        proxy_pass production;
}

vhost staging.tempesta-tech.com {
        req_hdr_set host "tempesta-tech.com";
        proxy_pass staging;
}

http_chain {
	# Redirect old URLs from the old static website
	uri == "/index"		-> 301 = /;
	uri == "/development-services" -> 301 = /network-security-performance-analysis;

	# Proably outdated redirects
	uri == "/index.html"	-> 301 = /;
	uri == "/services"	-> 301 = /development-services;
	uri == "/services.html"	-> 301 = /development-services;
	uri == "/c++-services"	-> 301 = /development-services;
	uri == "/company.html"	-> 301 = /company;
	uri == "/blog/fast-programming-languages-c-c++-rust-assembly" -> 301 = /blog/fast-programming-languages-c-cpp-rust-assembly;

	host == staging.tempesta-tech.com -> staging.tempesta-tech.com;
	host == "tempesta-tech.com" -> tempesta-tech.com;
}

and self-signed SAN (tempesta-tech.com and staging.tempesta-tech.com) nist256 EC certificate. Build Tempesta FW with DBG_HTTP=1 DBG_HTTP_PARSER=1 make clean all. Redirect local DNS for tempesta-tech.com and staging.tempesta-tech.com to the VM. Execute curl on the host system:

$ curl -Lvk --output /dev/null http://staging.tempesta-tech.com/
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0*   Trying 192.168.100.4:80...
* Connected to staging.tempesta-tech.com (192.168.100.4) port 80 (#0)
> GET / HTTP/1.1
> Host: staging.tempesta-tech.com
> User-Agent: curl/7.81.0
> Accept: */*
> 
  0     0    0     0    0     0      0      0 --:--:--  0:00:01 --:--:--     0* Mark bundle as not supporting multiuse
< HTTP/1.1 301 Moved Permanently
< Date: Mon, 19 Feb 2024 22:16:45 GMT
< X-Redirect-By: WordPress
< Location: https://tempesta-tech.com/
< Content-Length: 0
< Content-Type: text/html; charset=UTF-8
< via: 1.1 tempesta_fw (Tempesta FW 0.7.0)
< strict-transport-security: max-age=31536000; includeSubDomains
< Server: Tempesta FW/0.7.0
< 
  0     0    0     0    0     0      0      0 --:--:--  0:00:02 --:--:--     0
* Connection #0 to host staging.tempesta-tech.com left intact
* Clear auth, redirects to port from 80 to 443
* Issue another request to this URL: 'https://tempesta-tech.com/'
*   Trying 191.168.100.4:443...
  0     0    0     0    0     0      0      0 --:--:--  0:02:12 --:--:--     0* connect to 191.168.100.4 port 443 failed: Connection timed out
* Failed to connect to tempesta-tech.com port 443 after 130457 ms: Connection timed out
  0     0    0     0    0     0      0      0 --:--:--  0:02:12 --:--:--     0
* Closing connection 1
curl: (28) Failed to connect to tempesta-tech.com port 443 after 130457 ms: Connection timed out

Warning

With the curl command above I got this warning

[100568.005609] [tempesta fw] Tempesta FW is ready
[100725.936465] device ens3 entered promiscuous mode
[100738.616272] [tempesta fw]   parse 62 client data bytes (GET / HTTP/1.1
[100738.616272] Host: staging.tempesta-tech.com
[100738.616272] User-Agent: c) on req=00000000aff24cc2
[100738.620337] [tempesta fw]   parse 27 client data bytes (url/7.81.0
[100738.620337] Accept: */*
[100738.620337] 
[100738.620337] ) on req=00000000aff24cc2
[100740.654050] [tempesta fw]   parse 62 server data bytes (HTTP/1.1 301 Moved Permanently
[100740.654050] Date: Mon, 19 Feb 2024 22:16:4) on resp=00000000d91eec0a
[100740.657022] [tempesta fw]   parse 220 server data bytes (5 GMT
[100740.657022] Server: Apache/2.4.52 (Ubuntu)
[100740.657022] X-Redirect-By: WordPress
[100740.657022] Location: https://tempesta-tech.com/
[100740.657022] Content-Length: 0
[100740.657022] Keep-Alive: timeout=5, max=100
[100740.657022] Connection: Keep-Alive
[100740.657022] Content-Type: text/html; charset=UTF-8
[100740.657022] 
[100740.657022] ) on resp=00000000d91eec0a
[100740.664007] ------------[ cut here ]------------
[100740.664017] WARNING: CPU: 0 PID: 0 at /root/tempesta/fw/cache.c:2073 tfw_cache_copy_resp.isra.0+0xbd0/0xbe0 [tempesta_fw]
[100740.664901] Modules linked in: tempesta_fw(O) tempesta_db(O) tempesta_tls(O) tempesta_lib(O) bridge stp llc nf_tables nfnetlink ppdev serio_raw sg parport_pc parport button loop sch_fq_codel msr efi_pstore configfs ip_tables x_tables ext4 crc16 mbcache jbd2 efivars linear md_mod sr_mod cdrom ata_generic virtio_blk virtio_net net_failover failover ata_piix libata crct10dif_pclmul psmouse bochs_drm drm_vram_helper drm_ttm_helper ttm drm_kms_helper syscopyarea sysfillrect sysimgblt fb_sys_fops drm virtio_pci virtio_ring virtio scsi_mod i2c_piix4 [last unloaded: tempesta_lib]
[100740.665725] CPU: 0 PID: 0 Comm: swapper/0 Kdump: loaded Tainted: G           O      5.10.35-tfw-secperf+ #37
[100740.671259] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.15.0-1 04/01/2014
[100740.672073] RIP: 0010:tfw_cache_copy_resp.isra.0+0xbd0/0xbe0 [tempesta_fw]
[100740.672847] Code: ba af ea 85 c0 0f 84 d0 fa ff ff e9 2c 14 05 00 e8 e5 ba af ea 85 c0 0f 84 be fa ff ff e9 3c 14 05 00 8b 43 6c e9 bf fd ff ff <0f> 0b e9 aa fa ff ff 66 0f 1f 84 00 00 00 00 00 55 48 89 e5 41 57
[100740.673766] RSP: 0018:ffffb01380003920 EFLAGS: 00010202
[100740.675603] RAX: 0000000000000000 RBX: ffff932ce39b2020 RCX: ffff932ce39b2020
[100740.675987] RDX: ffffb01380003988 RSI: ffffb01380003980 RDI: ffff932ccf205038
[100740.676827] RBP: ffff932ce39b2950 R08: ffffb01380003970 R09: ffffffffc08fc920
[100740.677499] R10: ffff932ccf2051da R11: 000000000000002e R12: ffff932cf302b020
[100740.678321] R13: 0000000000000016 R14: ffffb01380003970 R15: ffff932ccf205010
[100740.679050] FS:  0000000000000000(0000) GS:ffff932df7c00000(0000) knlGS:0000000000000000
[100740.679928] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[100740.681130] CR2: 00007fc342bcdb90 CR3: 0000000122cec000 CR4: 0000000000750ef0
[100740.681928] PKRU: 55555554
[100740.683277] Call Trace:
[100740.683664]  <IRQ>
[100740.684166]  __cache_add_node+0xbc/0xd0 [tempesta_fw]
[100740.684732]  ? tfw_h2_resp_adjust_fwd+0x4b0/0x4b0 [tempesta_fw]
[100740.685604]  tfw_cache_add+0x17c/0x1b0 [tempesta_fw]
[100740.685940]  tfw_cache_process+0xa4/0x250 [tempesta_fw]
[100740.686579]  ? tfw_gfsm_move+0x18f/0x220 [tempesta_fw]
[100740.687217]  tfw_http_resp_cache+0xf6/0x190 [tempesta_fw]
[100740.687820]  tfw_http_resp_process+0x380/0x490 [tempesta_fw]
[100740.688365]  ? __get_free_pages+0x8/0x30
[100740.689047]  ? __tfw_pool_new+0x1b/0x50 [tempesta_fw]
[100740.689499]  ? __tfw_http_msg_alloc+0x20b/0x2e0 [tempesta_fw]
[100740.690116]  tfw_http_msg_process_generic+0x69/0x190 [tempesta_fw]
[100740.690684]  ? cpumask_next_and+0x19/0x20
[100740.691388]  ? update_sg_lb_stats+0x72/0x3c0
[100740.691935]  ? update_group_capacity+0x20/0x1d0
[100740.692388]  tfw_connection_recv+0x8f/0x110 [tempesta_fw]
[100740.692928]  ss_tcp_process_skb.constprop.0+0x11b/0x2d0 [tempesta_fw]
[100740.693566]  ss_tcp_process_data+0xdc/0x170 [tempesta_fw]
[100740.694159]  ss_tcp_data_ready+0x45/0x100 [tempesta_fw]
[100740.694843]  tcp_data_queue+0x391/0x550
[100740.695578]  tcp_rcv_established+0x217/0x620
[100740.695828]  tcp_v4_do_rcv+0x126/0x1e0
[100740.696529]  tcp_v4_rcv+0xbb4/0xce0
[100740.696906]  ? tcp_v4_early_demux+0xa3/0x140
[100740.697679]  ? tcp_v4_early_demux+0xe7/0x140
[100740.699118]  ip_protocol_deliver_rcu+0x14/0x170
[100740.699833]  ip_local_deliver_finish+0x3f/0x50
[100740.700553]  __netif_receive_skb_one_core+0x40/0x50
[100740.701194]  process_backlog+0x83/0x120
[100740.701719]  napi_poll+0x8a/0x1b0
[100740.702235]  net_rx_action+0x95/0x180
[100740.702686]  __do_softirq+0xc0/0x26e
[100740.703033]  asm_call_irq_on_stack+0xf/0x20
[100740.703548]  </IRQ>
[100740.704031]  do_softirq_own_stack+0x32/0x40
[100740.704421]  irq_exit_rcu+0x83/0xb0
[100740.705019]  sysvec_call_function_single+0x2e/0x80
[100740.705900]  asm_sysvec_call_function_single+0x12/0x20
[100740.706433] RIP: 0010:default_idle+0xe/0x10
[100740.706871] Code: fb 65 48 8b 04 25 00 6d 01 00 f0 80 60 02 df c3 0f ae f0 0f ae 38 0f ae f0 eb b6 90 e9 07 00 00 00 0f 00 2d c6 b6 47 00 fb f4 <c3> cc 65 8b 15 79 78 a8 54 89 d2 48 8b 05 e0 14 67 01 48 03 04 d5
[100740.708370] RSP: 0018:ffffffffabe03ec8 EFLAGS: 00000216
[100740.708922] RAX: ffff932df7c2ac40 RBX: ffffffffabe10940 RCX: ffff932df7c2ac40
[100740.709547] RDX: 00000000011dd39e RSI: 0000000000000087 RDI: 0000000000000000
[100740.710198] RBP: 0000000000000000 R08: ffff932df7c1dc40 R09: 0000000000000040
[100740.710862] R10: 0000000000000001 R11: 0000000000000000 R12: 0000000000000000
[100740.711516] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000
[100740.712178]  default_idle_call+0x2d/0xa0
[100740.712654]  cpuidle_idle_call+0x133/0x190
[100740.713210]  ? tsc_verify_tsc_adjust+0x2d/0xc0
[100740.713755]  do_idle+0x68/0xb0
[100740.714163]  cpu_startup_entry+0x14/0x20
[100740.715091]  start_kernel+0x43f/0x448
[100740.715553]  secondary_startup_64_no_verify+0xb0/0xbb
[100740.715887] ---[ end trace 3baa52260edda16d ]---
[100740.716218] [tempesta fw] 192.168.100.1 "staging.tempesta-tech.com" "GET / HTTP/1.1" 301 0 "-" "curl/7.81.0"
[109169.226057] perf: interrupt took too long (6002 > 5823), lowering kernel.perf_event_max_sample_rate to 33300
[131594.772646] device ens3 left promiscuous mode

This is

        if (WARN_ON_ONCE(tot_len != 0))
                return -EINVAL;

in tfw_cache_copy_resp().

I saw the warning only once.