JS/sticky cookie challenge fails

[krizhanovsky]

Scope

Tempesta FW with enabled JS challenge can not service a request from a browser. There was an external report for 0.6.2 release about the JS challenge failure with Warning: request dropped: sticky cookie challenge was failed. I tested the config as the below:

listen 80;
cache 1;
cache_fulfill * *;

sticky {
    cookie name=jdkey enforce max_misses=3 timeout=3; 
    js_challenge resp_code=503 delay_min=1000 delay_range=3000 delay_limit=300 /etc/tempesta/js_challenge.html;
}

block_action attack reply;

srv_group default {
    server 127.0.0.1:8080 conns_n=4;
}

vhost default {
    proxy_pass default;
}

http_chain {
    host == "debian" -> default;
     -> block;
}

frang_limits {
        request_rate 20;
        request_burst 15;
        connection_rate 8;
       connection_burst 6;
        concurrent_connections 8;
}

on current Tempesta FW master running in a VM with Apache HTTPD on loopback serving simple 2 byte index.html. I used Firefox browser on the host system to request Tempesta FW. I cleared cookies in the browser before the try.

I'm attaching the log of tcpdump tcpdump.txt ran on the host system. It seems the reason is that the browswer requests favicon.ico right after we sent the challenge, so Tempesta FW treats the request as an attack and blocks the browser.

Maybe related, but I'm not sure, with https://github.com/tempesta-tech/tempesta/issues/1102

The Tempesta FW log with DEBUG=3:

[  610.738690] [tdb] Start Tempesta DB
[  610.761951] [tempesta fw] Initializing Tempesta FW kernel module...
[  610.926039] [tempesta fw] Warning: Listening for HTTP/1.1 protocol is compatibility mode and may lack of performance.
[  610.928852] [tempesta fw] JavaScript challenge requires enforced sticky cookie mode
[  610.931276] [tempesta fw] Configuration processing is completed.
[  610.976865] [tdb] Opened table /opt/tempesta/db/filter.tdb: size=16777216 rec_size=20 base=ffff8cebbc400000
[  611.613788] [tdb] Opened table /opt/tempesta/db/cache.tdb: size=268435456 rec_size=0 base=ffff8cebac400000
[  611.623901] [tdb] Opened table /opt/tempesta/db/sessions.tdb: size=16777216 rec_size=312 base=ffff8cebab400000
[  613.908174] [tdb] Opened table /opt/tempesta/db/client.tdb: size=16777216 rec_size=616 base=ffff8cebaa400000
[  613.912386] [tempesta fw] Open listen socket on: 0.0.0.0
[  613.940217] [tempesta fw] modules are started
[  624.544513] [tempesta fw] Warning: request dropped: sticky cookie challenge was failed: 192.168.100.1
[  627.518319] [tempesta fw] Warning: request dropped: sticky cookie challenge was failed: 192.168.100.1
[ 2381.284187] [tdb] Close table 'client0.tdb'
[ 2381.301976] [tdb] Close table 'sessions0.tdb'
[ 2381.618574] [tdb] Close table 'cache0.tdb'
[ 2381.696924] [tdb] Close table 'filter0.tdb'
[ 2381.698826] [tempesta fw] modules are stopped
[ 2381.776935] [tempesta fw] exiting...
[ 2381.951736] [tdb] Shutdown Tempesta DB
[ 2382.173221] [tdb] Start Tempesta DB
[ 2382.201653] [tempesta fw] Initializing Tempesta FW kernel module...
[ 2382.203610] [tempesta fw]   init: pool
[ 2382.204717] [tempesta fw]   init: cfg
[ 2382.205905] [tempesta fw]   init: apm
[ 2382.206998] [tempesta fw]     tfw_mod_register: apm
[ 2382.208517] [tempesta fw]   init: vhost
[ 2382.209629] [tempesta fw]     tfw_mod_register: vhost
[ 2382.211006] [tempesta fw]   init: tls
[ 2382.212992] [tempesta fw]     tfw_mod_register: tls
[ 2382.214338] [tempesta fw]   init: http
[ 2382.215530] [tempesta fw]     tfw_mod_register: http
[ 2382.216831] [tempesta fw]   init: http_limits
[ 2382.218109] [tempesta fw]   Registering new classifier: frang
[ 2382.220209] [tempesta fw]   init: filter
[ 2382.221648] [tempesta fw]     tfw_mod_register: filter
[ 2382.224789] [tempesta fw]   init: cache
[ 2382.227727] [tempesta fw]     tfw_mod_register: cache
[ 2382.230559] [tempesta fw]   init: http_sess
[ 2382.232627] [tempesta fw]     tfw_mod_register: http_sess
[ 2382.234635] [tempesta fw]   init: sync_socket
[ 2382.236624] [tempesta fw]   init: server
[ 2382.238269] [tempesta fw]   init: client
[ 2382.240015] [tempesta fw]     tfw_mod_register: client
[ 2382.242216] [tempesta fw]   init: sock_srv
[ 2382.243846] [tempesta fw]     tfw_mod_register: sock_srv
[ 2382.245879] [tempesta fw]   init: sock_clnt
[ 2382.247618] [tempesta fw]     tfw_mod_register: sock_clnt
[ 2382.249623] [tempesta fw]   init: procfs
[ 2382.251409] [tempesta fw]     tfw_mod_register: procfs
[ 2382.255885] [tempesta fw]   init: http_tbl
[ 2382.259278] [tempesta fw]     tfw_mod_register: http_tbl
[ 2382.261935] [tempesta fw]   init: sched_hash
[ 2382.263746] [tempesta fw]   sched_hash: init
[ 2382.265420] [tempesta fw]   Registering new scheduler: hash
[ 2382.267708] [tempesta fw]   init: sched_ratio
[ 2382.269860] [tempesta fw]   ratio: init
[ 2382.271714] [tempesta fw]   Registering new scheduler: ratio
[ 2382.509378] [tempesta fw]     got state via sysctl: start
[ 2382.511281] [tempesta fw]     Prepare the configuration processing...
[ 2382.513277] [tempesta fw]     mod_cfgstart(): vhost
[ 2382.515034] [tempesta fw]     mod_cfgstart(): tls
[ 2382.516929] [tempesta fw]     mod_cfgstart(): http_sess
[ 2382.519332] [tempesta fw]     mod_cfgstart(): sock_srv
[ 2382.525036] [tempesta fw]   Create new server group: '__dfltopts__'
[ 2382.529097] [tempesta fw]   Create new server group: 'default'
[ 2382.532071] [tempesta fw]     mod_cfgstart(): http_tbl
[ 2382.533794] [tempesta fw]   Preparing for the configuration processing.
[ 2382.535836] [tempesta fw] Warning: Listening for HTTP/1.1 protocol is compatibility mode and may lack of performance.
[ 2382.538945] ------------[ cut here ]------------
[ 2382.540742] WARNING: CPU: 0 PID: 9321 at /root/tempesta/tempesta_fw/sock_clnt.c:535 tfw_cfgop_listen+0x19a/0x250 [tempesta_fw]
[ 2382.545489] Modules linked in: tempesta_fw(O) tempesta_db(O) tempesta_tls(O) tempesta_lib(O) binfmt_misc bochs_drm ttm crct10dif_pclmul drm_kms_helper drm fb_sys_fops ppdev sg syscopyarea sysfillrect sysimgblt serio_raw parport_pc parport button ip_tables x_tables ext4 crc16 mbcache jbd2 fscrypto sr_mod sd_mod cdrom ata_generic ata_piix libata psmouse scsi_mod e1000 i2c_piix4 [last unloaded: tempesta_lib]
[ 2382.560809] CPU: 0 PID: 9321 Comm: sysctl Tainted: G           O    4.14.32-kdump+ #147
[ 2382.563460] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS ?-20190727_073836-buildvm-ppc64le-16.ppc.fedoraproject.org-3.fc31 04/01/2014
[ 2382.567877] task: ffff8ceb9c8d8080 task.stack: ffff8ceb9943c000
[ 2382.570027] RIP: 0010:tfw_cfgop_listen+0x19a/0x250 [tempesta_fw]
[ 2382.572021] RSP: 0018:ffff8ceb9943f9f0 EFLAGS: 00010286
[ 2382.573792] RAX: 0000000000000069 RBX: 0000000000000000 RCX: 0000000000000000
[ 2382.576061] RDX: 0000000000000000 RSI: ffff8cebbfc15558 RDI: ffff8cebbfc15558
[ 2382.578378] RBP: ffff8ceb73718f40 R08: 0000000000000000 R09: 0000000000000200
[ 2382.580651] R10: 000000000000000a R11: 0000000000000001 R12: ffffffffc051f980
[ 2382.584687] R13: 0000000000000000 R14: ffff8ceb9943fb10 R15: ffffffffc051f820
[ 2382.588792] FS:  00007f0b4bfd9880(0000) GS:ffff8cebbfc00000(0000) knlGS:0000000000000000
[ 2382.591709] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 2382.593856] CR2: 00007fa65e8fe288 CR3: 000000004f7ae002 CR4: 00000000003606f0
[ 2382.596343] Call Trace:
[ 2382.597906]  ? read_next_token+0x21c/0x550 [tempesta_fw]
[ 2382.600101]  spec_handle_entry+0x7a/0x90 [tempesta_fw]
[ 2382.602098]  tfw_cfg_parse_mods+0x188/0x220 [tempesta_fw]
[ 2382.603998]  ? parse_cfg_entry+0x1b8/0x670 [tempesta_fw]
[ 2382.605893]  ? printk+0x4d/0x69
[ 2382.607444]  tfw_cfg_parse+0x43/0x90 [tempesta_fw]
[ 2382.609954]  tfw_ctlfn_state_io+0x226/0x520 [tempesta_fw]
[ 2382.612577]  ? mutex_lock+0x9/0x30
[ 2382.615021]  ? tfw_ctlfn_state_io+0x3c/0x520 [tempesta_fw]
[ 2382.618924]  ? cap_inode_getsecurity+0x220/0x220
[ 2382.621196]  proc_sys_call_handler+0xe8/0x110
[ 2382.623162]  __vfs_write+0x31/0x170
[ 2382.624945]  ? SYSC_newfstat+0x3c/0x60
[ 2382.626754]  vfs_write+0xab/0x190
[ 2382.628507]  SyS_write+0x4d/0xb0
[ 2382.630327]  do_syscall_64+0x61/0x110
[ 2382.632052]  entry_SYSCALL_64_after_hwframe+0x3d/0xa2
[ 2382.633986] RIP: 0033:0x7f0b4b769730
[ 2382.635670] RSP: 002b:00007ffc21909678 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
[ 2382.638078] RAX: ffffffffffffffda RBX: 0000000000000006 RCX: 00007f0b4b769730
[ 2382.640617] RDX: 0000000000000006 RSI: 000055ac797a42e0 RDI: 0000000000000004
[ 2382.644900] RBP: 000055ac797a42e0 R08: 00007f0b4bfd9880 R09: 000055ac797a40b0
[ 2382.649168] R10: 00007f0b4bfd9880 R11: 0000000000000246 R12: 0000000000000006
[ 2382.651791] R13: 0000000000000001 R14: 000055ac797a40b0 R15: 0000000000000006
[ 2382.654284] Code: 44 24 60 48 89 54 24 50 e9 22 ff ff ff 8b 35 ae aa 09 00 85 f6 0f 84 44 ff ff ff 31 db 48 c7 c7 a0 c9 4f c0 31 c0 e8 1c 90 a6 c6 <0f> 0b 83 fb 01 c7 05 87 aa 09 00 00 00 00 00 74 57 e9 1c ff ff 
[ 2382.660337] ---[ end trace fdbe46a8b26eb15e ]---
[ 2382.662844] [tempesta fw] JavaScript challenge requires enforced sticky cookie mode
[ 2382.665898] [tempesta fw]   Add new server group: 'default'
[ 2382.668133] [tempesta fw]   begin srv_group: default
[ 2382.670297] [tempesta fw]     Add new backend server to group 'default'
[ 2382.674051] [tempesta fw]   finish srv_group: default
[ 2382.677000] [tempesta fw]   http_tbl: begin http_chain
[ 2382.680411] [tempesta fw]   http_tbl: finish http_chain
[ 2382.682807] [tempesta fw]       parsed methods_mask: 0x0
[ 2382.684975] [tempesta fw]     Completing the configuration processing...
[ 2382.687305] [tempesta fw]     mod_cfgend(): apm
[ 2382.689308] [tempesta fw]     mod_cfgend(): vhost
[ 2382.691354] [tempesta fw]     mod_cfgend(): tls
[ 2382.693244] [tempesta fw]     mod_cfgend(): sock_srv
[ 2382.695281] [tempesta fw]     mod_cfgend(): sock_clnt
[ 2382.697211] [tempesta fw]   Checking backends and listeners
[ 2382.699338] [tempesta fw]       Checking server....
[ 2382.701289] [tempesta fw]       Iterating listener
[ 2382.705035] [tempesta fw]     mod_cfgend(): procfs
[ 2382.708629] [tempesta fw]     mod_cfgend(): http_tbl
[ 2382.711123] [tempesta fw] Configuration processing is completed.
[ 2382.713298] [tempesta fw]     starting modules...
[ 2382.715178] [tempesta fw]     mod_start(): vhost
[ 2382.748508] [tempesta fw]     mod_start(): tls
[ 2382.752687] [tempesta fw]     mod_start(): filter
[ 2382.772879] [tdb]   init db header: nwb=20480 db_size=16777216 rec_len=20
[ 2382.776942] [tdb] Opened table /opt/tempesta/db/filter.tdb: size=16777216 rec_size=20 base=ffff8cebbc400000
[ 2382.858574] [tempesta fw]     mod_start(): cache
[ 2383.012131] [tdb]   init db header: nwb=20480 db_size=268435456 rec_len=0
[ 2383.014700] [tdb] Opened table /opt/tempesta/db/cache.tdb: size=268435456 rec_size=0 base=ffff8cebac400000
[ 2383.017341] [tempesta fw]     mod_start(): http_sess
[ 2383.031100] [tdb]   init db header: nwb=20480 db_size=16777216 rec_len=312
[ 2383.035301] [tdb] Opened table /opt/tempesta/db/sessions.tdb: size=16777216 rec_size=312 base=ffff8cebab400000
[ 2383.040080] [tempesta fw]     mod_start(): client
[ 2383.057034] [tdb]   init db header: nwb=20480 db_size=16777216 rec_len=616
[ 2383.059682] [tdb] Opened table /opt/tempesta/db/client.tdb: size=16777216 rec_size=616 base=ffff8cebaa400000
[ 2383.064460] [tempesta fw]     mod_start(): sock_srv
[ 2383.067488] [tempesta fw]     Setup new group 'default' to use after reconfiguration
[ 2383.070940] [tempesta fw]   start server: 127.0.0.1:8080
[ 2383.073146] [tempesta fw]     Start scheduler 'ratio' for group 'default'
[ 2383.075541] [tempesta fw]     tfw_sched_ratio_add_grp_common: SG=[default]
[ 2383.078017] [tempesta fw]   Apply reconfig groups
[ 2383.080104] [tempesta fw]     Stop scheduler 'ratio' for group '__dfltopts__'
[ 2383.082720] [tempesta fw]     release group: '__dfltopts__'
[ 2383.084841] [tempesta fw]     mod_start(): sock_clnt
[ 2383.086776] [tempesta fw] Open listen socket on: 0.0.0.0
[ 2383.088860] connect: ipv4 mapped
[ 2383.088886] connect: ipv4 mapped
[ 2383.088891] connect: ipv4 mapped
[ 2383.088897] connect: ipv4 mapped
[ 2383.088935] [tempesta fw]     tfw_http_conn_init: conn=[ffff8ceb9c405780]
[ 2383.088936] [tempesta fw]   connected: 127.0.0.1:8080
[ 2383.088943] [tempesta fw]     tfw_http_conn_init: conn=[ffff8ceb9c405040]
[ 2383.088945] [tempesta fw]   connected: 127.0.0.1:8080
[ 2383.088950] [tempesta fw]     tfw_http_conn_init: conn=[ffff8ceb9c405b20]
[ 2383.088952] [tempesta fw]   connected: 127.0.0.1:8080
[ 2383.088955] [tempesta fw]     tfw_http_conn_init: conn=[ffff8ceb9c4053e0]
[ 2383.088956] [tempesta fw]   connected: 127.0.0.1:8080
[ 2383.114191] [tempesta fw]   start listening on socket: sk=ffff8ceb73af62c0
[ 2383.116319] [tempesta fw]     mod_start(): procfs
[ 2383.117990] [tempesta fw]     mod_start(): http_tbl
[ 2383.158531] [tempesta fw] modules are started
[ 2398.801035] [tdb]   Create a new htrie node for key=0x869aa30c00000000 len=616 bits_used=0
[ 2398.806256] [tdb]   alloc dblk 0x5000 for len=616(640)
[ 2398.809664] [tempesta fw]   new client: cli=ffff8cebaa405018
[ 2398.813894] [tempesta fw]   client address: 192.168.100.1
[ 2398.816982] [tempesta fw]     client ffff8cebaa405018, users=1
[ 2398.819174] [tempesta fw]       new client socket: sk=ffff8ceb8f87b300, state=1
[ 2398.821621] [tempesta fw]   client was found in tdb
[ 2398.824378] [tempesta fw]     client ffff8cebaa405018, users=2
[ 2398.828128] [tempesta fw]     tfw_http_conn_init: conn=[ffff8ceb9c4b94e0]
[ 2398.832173] [tempesta fw]       new client socket is accepted: sk=ffff8ceb8f87b300, conn=ffff8ceb9c4b94e0, cli=ffff8cebaa405018
[ 2398.839514] [tempesta fw]       GFSM exec fsm 0, state 0x2000
[ 2398.842079] [tempesta fw]     Link new msg ffff8ceb9cb93020 with connection ffff8ceb9c4b94e0
[ 2398.846499] [tempesta fw]     Add skb ffff8ceb8f1de000 to message ffff8ceb9cb93020
[ 2398.849410] [tempesta fw]     Received 394 client data bytes on conn=ffff8ceb9c4b94e0 msg=ffff8ceb9cb93020
[ 2398.853248] [tempesta fw]       tfw_match_ctext_vchar: str[0]=0x4d len=352 r=76
[ 2398.856287] [tempesta fw]       tfw_match_ctext_vchar: str[0]=0x65 len=184 r=14
[ 2398.859219] [tempesta fw]       tfw_match_ctext_vchar: str[0]=0x67 len=151 r=13
[ 2398.862795] [tempesta fw]       tfw_match_ctext_vchar: str[0]=0x31 len=131 r=1
[ 2398.865962] [tempesta fw]       tfw_match_ctext_vchar: str[0]=0x31 len=5 r=1
[ 2398.868413] [tempesta fw]     Request parsed: len=394 next=ffff8ceb8f1de000 parsed=394 msg_len=394 ver=3 res=0
[ 2398.871593] [tempesta fw]     Matching request: ffff8ceb9cb93020, list: ffff8ceb9cb9e050
[ 2398.874819] [tempesta fw]     Matching request: ffff8ceb9cb93020, list: ffff8ceb9cb9e060
[ 2398.878025] [tempesta fw]     rule: ffff8ceb9cb9e080, field: 0x3, op: 0x2, arg:5:6'debian'
[ 2398.881497] [tempesta fw]   Sticky cookie found: "jdkey" = "0000000100007eb2c7ec9600831f5f9a25ba5b6c634147e92df83b5b"
[ 2398.884670] [tempesta fw]   http_sess: calculate sticky cookie for 192.168.100.1, ts=0x100007eb2(now=0x1000333d2)...
[ 2398.887718] [tempesta fw]    ...secret: 0045fd992e70af8fac5fe78b009f96420de812d9
[ 2398.890297] [tempesta fw]    ...User-Agent: addr=ffff8ceb9c867648 skb=ffff8ceb8f1de000 len=76 flags=2 eolen=2:
[ 2398.893431] [tempesta fw]     duplicate ffff8ceb9c867648, len=76, flags=2 eolen=2:
[ 2398.897048] [tempesta fw]      len=76, eolen=0 ptr=ffff8ceb995271ac flags=0 'Mozilla/5.0 (X11; Fedora; Linux x86_64; rv:71.0) Gecko/20100101 Firefox/71.0'
[ 2398.901987] [tempesta fw] Warning: http_sess: bad received HMAC value for 192.168.100.1: c(pos=0), ts=0x100007eb2 orig_hmac=[be24b349db54ee9c58121a97ed249bc7879a8e14]
[ 2398.908116] ------------[ cut here ]------------
[ 2398.911006] WARNING: CPU: 1 PID: 14 at /root/tempesta/tempesta_fw/http_sess.c:763 tfw_http_sticky_verify+0x2dc/0x360 [tempesta_fw]
[ 2398.915485] Modules linked in: tempesta_fw(O) tempesta_db(O) tempesta_tls(O) tempesta_lib(O) binfmt_misc bochs_drm ttm crct10dif_pclmul drm_kms_helper drm fb_sys_fops ppdev sg syscopyarea sysfillrect sysimgblt serio_raw parport_pc parport button ip_tables x_tables ext4 crc16 mbcache jbd2 fscrypto sr_mod sd_mod cdrom ata_generic ata_piix libata psmouse scsi_mod e1000 i2c_piix4 [last unloaded: tempesta_lib]
[ 2398.927549] CPU: 1 PID: 14 Comm: ksoftirqd/1 Tainted: G        W  O    4.14.32-kdump+ #147
[ 2398.930451] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS ?-20190727_073836-buildvm-ppc64le-16.ppc.fedoraproject.org-3.fc31 04/01/2014
[ 2398.935644] task: ffff8ceb9d3fc1c0 task.stack: ffff8ceb9c864000
[ 2398.938185] RIP: 0010:tfw_http_sticky_verify+0x2dc/0x360 [tempesta_fw]
[ 2398.940800] RSP: 0018:ffff8ceb9c8676d8 EFLAGS: 00010286
[ 2398.943106] RAX: 000000000000009a RBX: 0000000000000000 RCX: 0000000000000006
[ 2398.945703] RDX: 0000000000000000 RSI: 0000000000000082 RDI: ffff8cebbfd15550
[ 2398.948237] RBP: ffff8ceb9c8677a8 R08: 0000000000000000 R09: 0000000000000286
[ 2398.950607] R10: ffffffff87a6ab00 R11: 0000000000000001 R12: ffff8ceb9c867898
[ 2398.952936] R13: ffff8ceb9c867718 R14: ffff8ceb7315a168 R15: ffff8ceb995272c2
[ 2398.955348] FS:  0000000000000000(0000) GS:ffff8cebbfd00000(0000) knlGS:0000000000000000
[ 2398.959193] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 2398.962043] CR2: 00007fa65e90a028 CR3: 000000002ca0a001 CR4: 00000000003606e0
[ 2398.965142] Call Trace:
[ 2398.967041]  ? tfw_http_sticky_verify+0x1fb/0x360 [tempesta_fw]
[ 2398.969404]  tfw_http_sticky_req_process+0x196/0x240 [tempesta_fw]
[ 2398.971726]  ? vprintk_emit+0x259/0x2c0
[ 2398.973846]  ? tfw_strcpy+0x2a0/0x2a0 [tempesta_fw]
[ 2398.975799]  tfw_http_sess_obtain+0xb1/0x250 [tempesta_fw]
[ 2398.978051]  tfw_http_msg_process_generic+0x439/0xdf0 [tempesta_fw]
[ 2398.980157]  ? up+0xd/0x50
[ 2398.981630]  ? irq_work_queue+0x8f/0xa0
[ 2398.983257]  ? console_unlock+0x2aa/0x4b0
[ 2398.984921]  ? vprintk_emit+0x259/0x2c0
[ 2398.986671]  tfw_http_msg_process+0x7f/0xc0 [tempesta_fw]
[ 2398.988921]  __gfsm_fsm_exec+0x6d/0xb0 [tempesta_fw]
[ 2398.991801]  tfw_connection_recv+0x3c/0x60 [tempesta_fw]
[ 2398.995042]  ? tfw_connection_send+0x20/0x20 [tempesta_fw]
[ 2398.997668]  ss_tcp_process_data+0x1e5/0x480 [tempesta_fw]
[ 2398.999948]  ss_tcp_data_ready+0x3e/0x90 [tempesta_fw]
[ 2399.002730]  tcp_data_queue+0x4f0/0xc50
[ 2399.005117]  tcp_rcv_established+0x277/0x570
[ 2399.007763]  tcp_v4_do_rcv+0x124/0x1c0
[ 2399.009617]  tcp_v4_rcv+0x93f/0xa40
[ 2399.011743]  ip_local_deliver_finish+0x95/0x1c0
[ 2399.013631]  ip_local_deliver+0x66/0xe0
[ 2399.015364]  ? tcp_v4_early_demux+0x10d/0x140
[ 2399.017281]  ? ip_rcv_finish+0x175/0x400
[ 2399.018988]  ip_rcv+0x284/0x3b0
[ 2399.020551]  ? inet_del_offload+0x30/0x30
[ 2399.022303]  __netif_receive_skb_core+0x84a/0xb30
[ 2399.025457]  ? slab_destroy+0x1f/0x50
[ 2399.027828]  ? slabs_destroy+0x50/0x70
[ 2399.029511]  ? __switch_to_asm+0x40/0x70
[ 2399.031090]  ? __switch_to_asm+0x34/0x70
[ 2399.032577]  ? __switch_to_asm+0x40/0x70
[ 2399.034075]  ? __switch_to_asm+0x34/0x70
[ 2399.035493]  ? process_backlog+0x92/0x120
[ 2399.037009]  process_backlog+0x92/0x120
[ 2399.038475]  net_rx_action+0x261/0x3a0
[ 2399.040048]  ? __switch_to_asm+0x40/0x70
[ 2399.041479]  __do_softirq+0x104/0x297
[ 2399.042902]  run_ksoftirqd+0x14/0x30
[ 2399.044354]  smpboot_thread_fn+0x109/0x160
[ 2399.045787]  kthread+0xfa/0x130
[ 2399.047132]  ? sort_range+0x20/0x20
[ 2399.048456]  ? kthread_create_on_node+0x60/0x60
[ 2399.049950]  ret_from_fork+0x35/0x40
[ 2399.051215] Code: fb 2e fa ff 41 0f b6 0f 54 48 8d 55 90 6a 28 4d 8b 0c 24 41 89 d8 48 c7 c6 ac a9 50 c0 48 c7 c7 e0 50 50 c0 31 c0 e8 7a d6 a0 c6 <0f> 0b 4c 89 ec e9 9c fe ff ff e8 f5 cb 9b c6 48 8d 7d 90 b9 36 
[ 2399.057132] ---[ end trace fdbe46a8b26eb15f ]---
[ 2399.059960] [tempesta fw]   http_sess: calculate redirection mark: ts=0x1000333e4(now=0x1000333e4), att_no=0x1
[ 2399.063974] [tempesta fw]       GFSM move 0x2000 -> 0x2: skb=ffff8ceb8f1de000 req=ffff8ceb9cb93020 resp=0000000000000000
[ 2399.068165] [tempesta fw]       GFSM switch from fsm 0 at state 2 to fsm 2 at state 0x400
[ 2399.071281] [tempesta fw]       GFSM exec fsm 2, state 0x2400
[ 2399.073269] [tempesta fw]   frang: check request for client 192.168.100.1, acc=ffff8cebaa405048
[ 2399.075784] [tempesta fw]   frang: check incomplete request headers for client 192.168.100.1, acc=ffff8cebaa405048
[ 2399.079075] [tempesta fw]       enter frang FSM at state 0x0(Frang_Req_0)
[ 2399.081807] [tempesta fw]       enter frang FSM at state 0x1(Frang_Req_Hdr_Method)
[ 2399.085795] [tempesta fw]       enter frang FSM at state 0x2(Frang_Req_Hdr_UriLen)
[ 2399.087971] [tempesta fw]       enter frang FSM at state 0x3(Frang_Req_Hdr_Check)
[ 2399.090441] [tempesta fw]       enter frang FSM at state 0x5(Frang_Req_Body_Start)
[ 2399.094161] [tempesta fw]   frang: check incomplete request body for client 192.168.100.1, acc=ffff8cebaa405048
[ 2399.096901] [tempesta fw]       enter frang FSM at state 0x6(Frang_Req_Body)
[ 2399.099109] [tempesta fw]       enter frang FSM at state 0x8(Frang_Req_Trailer)
[ 2399.101371] [tempesta fw]       enter frang FSM at state 0x9(Frang_Req_Done)
[ 2399.103852] [tempesta fw]   frang: checks done for client 192.168.100.1
[ 2399.107188] [tempesta fw]       GFSM move 0x2400 -> 0x41f: skb=ffff8ceb8f1de000 req=ffff8ceb9cb93020 resp=0000000000000000
[ 2399.110502] [tempesta fw]       Finish frang FSM at state 0x9, ret=0
[ 2399.112598] [tempesta fw]       TFW_HTTP_FSM_REQ_MSG return code 0
[ 2399.114544] [tempesta fw]     tfw_http_resp_fwd: req=[ffff8ceb9cb93020], resp=[ffff8ceb8f8a7020]
[ 2399.286013] [tempesta fw]       GFSM exec fsm 0, state 0x2002
[ 2399.289358] [tempesta fw]     Link new msg ffff8ceb9cb93020 with connection ffff8ceb9c4b94e0
[ 2399.294749] [tempesta fw]     Add skb ffff8ceb72e93d00 to message ffff8ceb9cb93020
[ 2399.298838] [tempesta fw]     Received 326 client data bytes on conn=ffff8ceb9c4b94e0 msg=ffff8ceb9cb93020
[ 2399.303131] [tempesta fw]       tfw_match_ctext_vchar: str[0]=0x4d len=273 r=76
[ 2399.306704] [tempesta fw]       tfw_match_ctext_vchar: str[0]=0x65 len=154 r=14
[ 2399.310352] [tempesta fw]       tfw_match_ctext_vchar: str[0]=0x67 len=121 r=13
[ 2399.313639] [tempesta fw]       tfw_match_ctext_vchar: str[0]=0x31 len=101 r=1
[ 2399.317243] [tempesta fw]     Request parsed: len=326 next=ffff8ceb72e93d00 parsed=326 msg_len=326 ver=3 res=0
[ 2399.321906] [tempesta fw]     Matching request: ffff8ceb9cb93020, list: ffff8ceb9cb9e050
[ 2399.326490] [tempesta fw]     Matching request: ffff8ceb9cb93020, list: ffff8ceb9cb9e060
[ 2399.330418] [tempesta fw]     rule: ffff8ceb9cb9e080, field: 0x3, op: 0x2, arg:5:6'debian'
[ 2399.335339] [tempesta fw]   Sticky cookie found: "jdkey" = "0000000100007eb2be24b349db54ee9c58121a97ed249bc7879a8e14"
[ 2399.340125] [tempesta fw]   http_sess: calculate sticky cookie for 192.168.100.1, ts=0x100007eb2(now=0x100033400)...
[ 2399.343672] [tempesta fw]    ...secret: 0045fd992e70af8fac5fe78b009f96420de812d9
[ 2399.347369] [tempesta fw]    ...User-Agent: addr=ffff8cebbfd03780 skb=ffff8ceb72e93d00 len=76 flags=2 eolen=2:
[ 2399.351602] [tempesta fw]     duplicate ffff8cebbfd03780, len=76, flags=2 eolen=2:
[ 2399.355625] [tempesta fw]      len=76, eolen=0 ptr=ffff8ceb99525b37 flags=0 'Mozilla/5.0 (X11; Fedora; Linux x86_64; rv:71.0) Gecko/20100101 Firefox/71.0'
[ 2399.363930] [tempesta fw]   sess: jsch block: request received outside allowed time range.
[ 2399.367638] [tempesta fw] Warning: request dropped: sticky cookie challenge was failed: 192.168.100.1
[ 2399.371268] ------------[ cut here ]------------
[ 2399.373802] WARNING: CPU: 1 PID: 0 at /root/tempesta/tempesta_fw/http.c:4464 tfw_http_cli_error_resp_and_log+0x38e/0x3a0 [tempesta_fw]
[ 2399.380251] Modules linked in: tempesta_fw(O) tempesta_db(O) tempesta_tls(O) tempesta_lib(O) binfmt_misc bochs_drm ttm crct10dif_pclmul drm_kms_helper drm fb_sys_fops ppdev sg syscopyarea sysfillrect sysimgblt serio_raw parport_pc parport button ip_tables x_tables ext4 crc16 mbcache jbd2 fscrypto sr_mod sd_mod cdrom ata_generic ata_piix libata psmouse scsi_mod e1000 i2c_piix4 [last unloaded: tempesta_lib]
[ 2399.391565] CPU: 1 PID: 0 Comm: swapper/1 Tainted: G        W  O    4.14.32-kdump+ #147
[ 2399.394088] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS ?-20190727_073836-buildvm-ppc64le-16.ppc.fedoraproject.org-3.fc31 04/01/2014
[ 2399.400384] task: ffff8ceb9d3f50c0 task.stack: ffff8ceb9c854000
[ 2399.402940] RIP: 0010:tfw_http_cli_error_resp_and_log+0x38e/0x3a0 [tempesta_fw]
[ 2399.406397] RSP: 0018:ffff8cebbfd039e0 EFLAGS: 00010282
[ 2399.410009] RAX: 0000000000000059 RBX: ffff8ceb9cb93020 RCX: 0000000000000000
[ 2399.413966] RDX: 0000000000000000 RSI: 00000000000000f6 RDI: 0000000000000300
[ 2399.418205] RBP: 0000000000000001 R08: 0000000000000000 R09: 00000000000002ed
[ 2399.422171] R10: ffff8cebab400088 R11: 0000000000000001 R12: 00000000000001f7
[ 2399.425362] R13: ffffffffc0508958 R14: 0000000000000001 R15: 0000000000000001
[ 2399.429039] FS:  0000000000000000(0000) GS:ffff8cebbfd00000(0000) knlGS:0000000000000000
[ 2399.431646] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 2399.433567] CR2: 00007fa65e90a028 CR3: 000000002ca0a001 CR4: 00000000003606e0
[ 2399.435769] Call Trace:
[ 2399.437222]  <IRQ>
[ 2399.438503]  tfw_http_msg_process_generic+0xa3b/0xdf0 [tempesta_fw]
[ 2399.441189]  ? native_apic_mem_write+0x10/0x10
[ 2399.443569]  ? native_apic_wait_icr_idle+0x1c/0x30
[ 2399.446355]  ? irq_work_queue+0x98/0xa0
[ 2399.447888]  ? console_unlock+0x2aa/0x4b0
[ 2399.449538]  ? vprintk_emit+0x259/0x2c0
[ 2399.451090]  ? eth_header+0x20/0xb0
[ 2399.453777]  tfw_http_msg_process+0x7f/0xc0 [tempesta_fw]
[ 2399.456091]  __gfsm_fsm_exec+0x6d/0xb0 [tempesta_fw]
[ 2399.458409]  tfw_connection_recv+0x3c/0x60 [tempesta_fw]
[ 2399.461257]  ? tfw_connection_send+0x20/0x20 [tempesta_fw]
[ 2399.463342]  ss_tcp_process_data+0x1e5/0x480 [tempesta_fw]
[ 2399.465274]  ? tcp_transmit_skb+0x530/0x9c0
[ 2399.466858]  ss_tcp_data_ready+0x3e/0x90 [tempesta_fw]
[ 2399.468616]  tcp_rcv_established+0x4cd/0x570
[ 2399.470250]  tcp_v4_do_rcv+0x124/0x1c0
[ 2399.471709]  tcp_v4_rcv+0x93f/0xa40
[ 2399.473730]  ip_local_deliver_finish+0x95/0x1c0
[ 2399.477065]  ip_local_deliver+0x66/0xe0
[ 2399.479070]  ? tcp_v4_early_demux+0x10d/0x140
[ 2399.480690]  ? ip_rcv_finish+0x175/0x400
[ 2399.483473]  ip_rcv+0x284/0x3b0
[ 2399.486126]  ? inet_del_offload+0x30/0x30
[ 2399.488235]  __netif_receive_skb_core+0x84a/0xb30
[ 2399.490470]  ? e1000_clean+0x36f/0x8c0 [e1000]
[ 2399.492855]  ? process_backlog+0x92/0x120
[ 2399.495125]  process_backlog+0x92/0x120
[ 2399.496589]  net_rx_action+0x261/0x3a0
[ 2399.497871]  __do_softirq+0x104/0x297
[ 2399.499161]  irq_exit+0xa3/0xb0
[ 2399.500347]  do_IRQ+0x45/0xc0
[ 2399.501438]  common_interrupt+0x7a/0x7a
[ 2399.503196]  </IRQ>
[ 2399.505221] RIP: 0010:default_idle+0x12/0xf0
[ 2399.507630] RSP: 0018:ffff8ceb9c857ec0 EFLAGS: 00000246 ORIG_RAX: ffffffffffffffc4
[ 2399.511168] RAX: ffffffff87428510 RBX: ffff8ceb9d3f50c0 RCX: 0000000000000000
[ 2399.513179] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000000
[ 2399.515101] RBP: 0000000000000001 R08: 0000000000000002 R09: ffffffff87e084e8
[ 2399.516997] R10: 0000000000022ec6 R11: 0000000000000000 R12: ffff8ceb9d3f50c0
[ 2399.518825] R13: ffff8ceb9d3f50c0 R14: 0000000000000000 R15: 0000000000000000
[ 2399.520652]  ? __sched_text_end+0x3/0x3
[ 2399.521876]  do_idle+0x156/0x1b0
[ 2399.523304]  cpu_startup_entry+0x6a/0x70
[ 2399.524924]  start_secondary+0x188/0x1b0
[ 2399.527167]  secondary_startup_64+0xa5/0xb0
[ 2399.528778] Code: 00 00 be 01 00 00 00 48 8b b8 40 03 00 00 48 83 c7 14 e8 d6 3e f9 ff 4c 89 ee 48 89 e2 48 c7 c7 d8 74 50 c0 31 c0 e8 68 e6 9f c6 <0f> 0b e9 cb fc ff ff 90 66 2e 0f 1f 84 00 00 00 00 00 41 55 41 
[ 2399.533317] ---[ end trace fdbe46a8b26eb160 ]---
[ 2399.535245] [tempesta fw]     tfw_http_resp_fwd: req=[ffff8ceb9cb93020], resp=[ffff8ceb8f8a7020]
[ 2399.539314] [tempesta fw]       connection lost: close client socket: sk=ffff8ceb8f87b300, conn=ffff8ceb9c4b94e0, client=ffff8cebaa405018
[ 2399.545157] [tempesta fw]     tfw_http_conn_drop: conn=[ffff8ceb9c4b94e0]
[ 2399.547123] [tempesta fw]     tfw_http_conn_cli_drop: conn=[ffff8ceb9c4b94e0]
[ 2399.549058] [tempesta fw]     put client ffff8cebaa405018, users=2
[ 2399.551283] [tempesta fw]     put client ffff8cebaa405018, users=1
[ 2399.553164] [tempesta fw]   put client: cli=ffff8cebaa405018
[ 2402.335682] [tempesta fw]   client was found in tdb
[ 2402.339644] [tempesta fw]     client ffff8cebaa405018, users=1
[ 2402.342807] [tempesta fw]       new client socket: sk=ffff8ceb8f87b300, state=1
[ 2402.346974] [tempesta fw]   client was found in tdb
[ 2402.349393] [tempesta fw]     client ffff8cebaa405018, users=2
[ 2402.351382] [tempesta fw]     tfw_http_conn_init: conn=[ffff8ceb9c4b94e0]
[ 2402.353474] [tempesta fw]       new client socket is accepted: sk=ffff8ceb8f87b300, conn=ffff8ceb9c4b94e0, cli=ffff8cebaa405018
[ 2402.358095] [tempesta fw]       GFSM exec fsm 0, state 0x2000
[ 2402.361683] [tempesta fw]     Link new msg ffff8ceb9cb93020 with connection ffff8ceb9c4b94e0
[ 2402.364667] [tempesta fw]     Add skb ffff8ceb73ab9f00 to message ffff8ceb9cb93020
[ 2402.367704] [tempesta fw]     Received 420 client data bytes on conn=ffff8ceb9c4b94e0 msg=ffff8ceb9cb93020
[ 2402.370960] [tempesta fw]       tfw_match_ctext_vchar: str[0]=0x4d len=378 r=76
[ 2402.373450] [tempesta fw]       tfw_match_ctext_vchar: str[0]=0x65 len=210 r=14
[ 2402.376015] [tempesta fw]       tfw_match_ctext_vchar: str[0]=0x67 len=177 r=13
[ 2402.379077] [tempesta fw]       tfw_match_ctext_vchar: str[0]=0x31 len=157 r=1
[ 2402.381744] [tempesta fw]       tfw_match_ctext_vchar: str[0]=0x31 len=31 r=1
[ 2402.383994] [tempesta fw]     Request parsed: len=420 next=ffff8ceb73ab9f00 parsed=420 msg_len=420 ver=3 res=0
[ 2402.387229] [tempesta fw]     Matching request: ffff8ceb9cb93020, list: ffff8ceb9cb9e050
[ 2402.389343] [tempesta fw]     Matching request: ffff8ceb9cb93020, list: ffff8ceb9cb9e060
[ 2402.391559] [tempesta fw]     rule: ffff8ceb9cb9e080, field: 0x3, op: 0x2, arg:5:6'debian'
[ 2402.394844] [tempesta fw]   Sticky cookie found: "jdkey" = "0000000100007eb2be24b349db54ee9c58121a97ed249bc7879a8e14"
[ 2402.398439] [tempesta fw]   http_sess: calculate sticky cookie for 192.168.100.1, ts=0x100007eb2(now=0x100033531)...
[ 2402.401523] [tempesta fw]    ...secret: 0045fd992e70af8fac5fe78b009f96420de812d9
[ 2402.403876] [tempesta fw]    ...User-Agent: addr=ffff8ceb9c867648 skb=ffff8ceb73ab9f00 len=76 flags=2 eolen=2:
[ 2402.406443] [tempesta fw]     duplicate ffff8ceb9c867648, len=76, flags=2 eolen=2:
[ 2402.409119] [tempesta fw]      len=76, eolen=0 ptr=ffff8ceb995235ac flags=0 'Mozilla/5.0 (X11; Fedora; Linux x86_64; rv:71.0) Gecko/20100101 Firefox/71.0'
[ 2402.415649] [tempesta fw]   sess: jsch block: request received outside allowed time range.
[ 2402.418335] [tempesta fw] Warning: request dropped: sticky cookie challenge was failed: 192.168.100.1
[ 2402.420881] ------------[ cut here ]------------
[ 2402.422650] WARNING: CPU: 1 PID: 14 at /root/tempesta/tempesta_fw/http.c:4464 tfw_http_cli_error_resp_and_log+0x38e/0x3a0 [tempesta_fw]
[ 2402.427454] Modules linked in: tempesta_fw(O) tempesta_db(O) tempesta_tls(O) tempesta_lib(O) binfmt_misc bochs_drm ttm crct10dif_pclmul drm_kms_helper drm fb_sys_fops ppdev sg syscopyarea sysfillrect sysimgblt serio_raw parport_pc parport button ip_tables x_tables ext4 crc16 mbcache jbd2 fscrypto sr_mod sd_mod cdrom ata_generic ata_piix libata psmouse scsi_mod e1000 i2c_piix4 [last unloaded: tempesta_lib]
[ 2402.439068] CPU: 1 PID: 14 Comm: ksoftirqd/1 Tainted: G        W  O    4.14.32-kdump+ #147
[ 2402.441965] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS ?-20190727_073836-buildvm-ppc64le-16.ppc.fedoraproject.org-3.fc31 04/01/2014
[ 2402.448940] task: ffff8ceb9d3fc1c0 task.stack: ffff8ceb9c864000
[ 2402.451258] RIP: 0010:tfw_http_cli_error_resp_and_log+0x38e/0x3a0 [tempesta_fw]
[ 2402.453499] RSP: 0018:ffff8ceb9c8678a8 EFLAGS: 00010286
[ 2402.455389] RAX: 0000000000000059 RBX: ffff8ceb9cb93020 RCX: 0000000000000000
[ 2402.457697] RDX: 0000000000000000 RSI: ffff8cebbfd15558 RDI: ffff8cebbfd15558
[ 2402.461072] RBP: 0000000000000001 R08: 0000000000000000 R09: 0000000000000351
[ 2402.464516] R10: ffff8cebab400088 R11: 0000000000000001 R12: 00000000000001f7
[ 2402.466825] R13: ffffffffc0508958 R14: 0000000000000001 R15: 0000000000000001
[ 2402.469085] FS:  0000000000000000(0000) GS:ffff8cebbfd00000(0000) knlGS:0000000000000000
[ 2402.471540] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 2402.473538] CR2: 00007f8700034658 CR3: 000000002ca0a001 CR4: 00000000003606e0
[ 2402.477338] Call Trace:
[ 2402.479645]  tfw_http_msg_process_generic+0xa3b/0xdf0 [tempesta_fw]
[ 2402.482001]  ? up+0xd/0x50
[ 2402.483476]  ? irq_work_queue+0x8f/0xa0
[ 2402.485023]  ? console_unlock+0x2aa/0x4b0
[ 2402.486649]  ? vprintk_emit+0x259/0x2c0
[ 2402.488379]  tfw_http_msg_process+0x7f/0xc0 [tempesta_fw]
[ 2402.490276]  __gfsm_fsm_exec+0x6d/0xb0 [tempesta_fw]
[ 2402.492195]  ? up+0xd/0x50
[ 2402.494047]  tfw_connection_recv+0x3c/0x60 [tempesta_fw]
[ 2402.496310]  ? tfw_connection_send+0x20/0x20 [tempesta_fw]
[ 2402.498301]  ss_tcp_process_data+0x1e5/0x480 [tempesta_fw]
[ 2402.500281]  ? vprintk_emit+0x259/0x2c0
[ 2402.502115]  ss_tcp_data_ready+0x3e/0x90 [tempesta_fw]
[ 2402.503896]  tcp_data_queue+0x4f0/0xc50
[ 2402.506017]  tcp_rcv_established+0x277/0x570
[ 2402.507721]  tcp_v4_do_rcv+0x124/0x1c0
[ 2402.510081]  tcp_v4_rcv+0x93f/0xa40
[ 2402.512409]  ip_local_deliver_finish+0x95/0x1c0
[ 2402.514681]  ip_local_deliver+0x66/0xe0
[ 2402.516381]  ? tcp_v4_early_demux+0x10d/0x140
[ 2402.518019]  ? ip_rcv_finish+0x175/0x400
[ 2402.519612]  ip_rcv+0x284/0x3b0
[ 2402.520938]  ? inet_del_offload+0x30/0x30
[ 2402.522431]  __netif_receive_skb_core+0x84a/0xb30
[ 2402.523960]  ? process_backlog+0x92/0x120
[ 2402.525680]  process_backlog+0x92/0x120
[ 2402.527412]  net_rx_action+0x261/0x3a0
[ 2402.528916]  ? __switch_to_asm+0x40/0x70
[ 2402.530379]  __do_softirq+0x104/0x297
[ 2402.531615]  run_ksoftirqd+0x14/0x30
[ 2402.532856]  smpboot_thread_fn+0x109/0x160
[ 2402.534205]  kthread+0xfa/0x130
[ 2402.535793]  ? sort_range+0x20/0x20
[ 2402.537072]  ? kthread_create_on_node+0x60/0x60
[ 2402.538718]  ret_from_fork+0x35/0x40
[ 2402.539978] Code: 00 00 be 01 00 00 00 48 8b b8 40 03 00 00 48 83 c7 14 e8 d6 3e f9 ff 4c 89 ee 48 89 e2 48 c7 c7 d8 74 50 c0 31 c0 e8 68 e6 9f c6 <0f> 0b e9 cb fc ff ff 90 66 2e 0f 1f 84 00 00 00 00 00 41 55 41 
[ 2402.545941] ---[ end trace fdbe46a8b26eb161 ]---
[ 2402.547869] [tempesta fw]     tfw_http_resp_fwd: req=[ffff8ceb9cb93020], resp=[ffff8ceb8f8a7020]
[ 2402.550958] [tempesta fw]       connection lost: close client socket: sk=ffff8ceb8f87b300, conn=ffff8ceb9c4b94e0, client=ffff8cebaa405018
[ 2402.555830] [tempesta fw]     tfw_http_conn_drop: conn=[ffff8ceb9c4b94e0]
[ 2402.557826] [tempesta fw]     tfw_http_conn_cli_drop: conn=[ffff8ceb9c4b94e0]
[ 2402.560605] [tempesta fw]     put client ffff8cebaa405018, users=2
[ 2402.564445] [tempesta fw]     put client ffff8cebaa405018, users=1
[ 2402.566961] [tempesta fw]   put client: cli=ffff8cebaa405018
[ 2435.361607] [tempesta fw]   connection error: 127.0.0.1:8080
[ 2435.362212] [tempesta fw]   connection error: 127.0.0.1:8080
[ 2435.362218] [tempesta fw]     tfw_http_conn_drop: conn=[ffff8ceb9c405780]
[ 2435.362223] [tempesta fw]     tfw_http_conn_release: conn=[ffff8ceb9c405780]
[ 2435.362543] [tempesta fw]   connection error: 127.0.0.1:8080
[ 2435.362549] [tempesta fw]     tfw_http_conn_drop: conn=[ffff8ceb9c405040]
[ 2435.362552] [tempesta fw]     tfw_http_conn_release: conn=[ffff8ceb9c405040]

Testing

• [ ] Test the scenario with at least 2 browswers (Chrome and Firefox)
• [ ] Test with cleared cookies and left from the last session

Also please

• [ ] update https://github.com/tempesta-tech/tempesta/issues/923 with the scenario of the real reason for the bug - we need to reproduce the case automaticlly.

[vankoven]

I also noticed max_misses misbehaviour while testing the issue. js_challenge directive was removed from configuration above. Chome initially connects to http://192.168.122.12/some_uri and receives redirect to http://192.168.122.12/jdkey=000000010000000103fbbecb5ebf05fd3610ba349be9723c06755e03db976195/some_uri. But then instead of stripping redirect tag, the request is passed to origin, and Chrome gets 404 error from origin server. No errors appear in Tempesta log, but browser actually passed the challenge, next request in the same browser session gives the site content.

[vankoven]

There is definitely relation to #1102 . But this doesn't related to instant failure of JS challenge, it doesn't allow user to reconnect if he has an old sticky cookie value and no session stored in Tempesta databases. Need to rerun JS challenge after some time, e.g. after delay_min + delay_range + ...

[krizhanovsky]

js_challenge.html.txt The redirection file from my test

[vankoven]

The redirection file from my test

Yeah, this file from some very-very old installation, it had issues with reading cookie value from response, thus no delay was done between reties and Tempesta blocked client. I also experienced absolutely the same issue (: Took me some time to discover that.

[vankoven]

The issue was faced because we erroneously treated all requests with header Accept: */* header as supporting cookies. That was the biggest mistake I've done on JS challenge implementation, trying to support challenge for any link typed into browser's search bar.

Actually browsers sends Accept: */* in every request, so all requests was treated as challengeable, which can lead to false challenge fails. As client follows some link or manually enters a line into search bar, the very first request is used to load DOM. This request always has Accept: text/html and is the right target for JS challenge. In the same time. Even if the uri is direct link to some image, thus any first request to the protected site will imply Accept: text/html header.

The issue I saw with JS challenge stability in some cases was because of unlucky coincidence related connection close on second request (request for favicon.ico). After Accept issue was fixed, JS challenge started to work reliable.

[krizhanovsky]

Just tried a clean setup from with current #1395. Deployed our website under Apache HTTPD. Sent several requests with Firefow and Chrome, one after another. There were warnings about bad cookies and ratelimits, just wait a little bit and press Refresh in a browser. Got this crash (didn't check this on master):

[  137.693007] [tempesta fw] Warning: http_sess: bad received HMAC value for 192.168.100.1: 7(pos=0), ts=0xffffc14e orig_hmac=[a33793fd52f9bc1d5786ca2f27fc762790f3c4ee]
[  140.000413] [tempesta fw] Warning: request dropped: sticky cookie challenge was failed: 192.168.100.1
[  160.318895] [tempesta fw] Warning: frang: connections max num. exceeded for 192.168.100.1: 9 (lim=8)
[  161.777545] [tempesta fw] Warning: frang: connections max num. exceeded for 192.168.100.1: 9 (lim=8)
[  161.784842] [tempesta fw] Warning: frang: connections max num. exceeded for 192.168.100.1: 9 (lim=8)
[  161.792483] [tempesta fw] Warning: frang: connections max num. exceeded for 192.168.100.1: 9 (lim=8)
[  161.796213] [tempesta fw] Warning: frang: connections max num. exceeded for 192.168.100.1: 9 (lim=8)
[  161.855332] general protection fault: 0000 [#1] SMP PTI
[  161.857284] Modules linked in: tempesta_fw(O) tempesta_db(O) tempesta_tls(O) tempesta_lib(O) binfmt_misc crct10dif_pclmul bochs_drm ttm drm_kms_helper drm fb_sys_fops syscopyarea sysfillrect ppdev sysimgblt sg serio_raw parport_pc parport button ip_tables x_tables ext4 crc16 mbcache jbd2 fscrypto sd_mod sr_mod cdrom ata_generic ata_piix libata e1000 scsi_mod i2c_piix4 psmouse
[  161.868959] CPU: 1 PID: 0 Comm: swapper/1 Tainted: G           O    4.14.32-kdump+ #147
[  161.872214] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS ?-20190727_073836-buildvm-ppc64le-16.ppc.fedoraproject.org-3.fc31 04/01/2014
[  161.877325] task: ffff9de6663f50c0 task.stack: ffff9de666854000
[  161.880072] RIP: 0010:__memcpy_fast+0x148/0x160 [tempesta_lib]
[  161.882486] RSP: 0018:ffff9de67fd03878 EFLAGS: 00010286
[  161.885785] RAX: 00013da600000002 RBX: 0000000000000000 RCX: ffffffffc05648b4
[  161.888860] RDX: 0000000000000002 RSI: 0000000000000a0d RDI: 00013da600000000
[  161.890536] RBP: ffffffffc057bc40 R08: ffffffffc05648b2 R09: ffff9de666d20cc0
[  161.892585] R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000002
[  161.894708] R13: 0000000000001000 R14: 0000000000000002 R15: ffff9de666d39188
[  161.897048] FS:  0000000000000000(0000) GS:ffff9de67fd00000(0000) knlGS:0000000000000000
[  161.899298] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  161.902892] CR2: 00007fdb59ff9fe8 CR3: 000000006520a001 CR4: 00000000003606e0
[  161.905441] Call Trace:
[  161.907198]  <IRQ>
[  161.908975]  tfw_http_msg_expand_data+0x11b/0x370 [tempesta_fw]
[  161.911502]  ? tfw_http_conn_drop+0x250/0x250 [tempesta_fw]
[  161.913725]  tfw_cache_do_action+0xd43/0xdf0 [tempesta_fw]
[  161.916541]  ? tfw_hash_str_len+0x147/0x160 [tempesta_fw]
[  161.918822]  ? tfw_http_sticky_add+0x270/0x270 [tempesta_fw]
[  161.921319]  ? tfw_http_conn_drop+0x250/0x250 [tempesta_fw]
[  161.922971]  ? tfw_http_req_key_calc+0xc5/0xe0 [tempesta_fw]
[  161.924387]  ? tfw_http_conn_drop+0x250/0x250 [tempesta_fw]
[  161.925773]  tfw_cache_process+0xb7/0x290 [tempesta_fw]
[  161.927703]  ? tfw_gfsm_move+0x146/0x180 [tempesta_fw]
[  161.928982]  tfw_http_msg_process_generic+0x745/0xcf0 [tempesta_fw]
[  161.930365]  ? mod_timer+0x16c/0x3a0
[  161.931499]  tfw_http_msg_process+0x7f/0xc0 [tempesta_fw]
[  161.934569]  __gfsm_fsm_exec+0x51/0x90 [tempesta_fw]
[  161.936375]  tfw_connection_recv+0x3c/0x60 [tempesta_fw]
[  161.938471]  ? tfw_connection_send+0x20/0x20 [tempesta_fw]
[  161.939892]  ss_tcp_process_data+0x1e5/0x480 [tempesta_fw]
[  161.941169]  ? mod_timer+0x16c/0x3a0
[  161.942230]  ss_tcp_data_ready+0x3e/0x90 [tempesta_fw]
[  161.943485]  tcp_rcv_established+0x4cd/0x570
[  161.944669]  tcp_v4_do_rcv+0x124/0x1c0
[  161.945722]  tcp_v4_rcv+0x93f/0xa40
[  161.946722]  ip_local_deliver_finish+0x95/0x1c0
[  161.947911]  ip_local_deliver+0x66/0xe0
[  161.949649]  ? tcp_v4_early_demux+0x10d/0x140
[  161.951257]  ? ip_rcv_finish+0x175/0x400
[  161.952886]  ip_rcv+0x284/0x3b0
[  161.953894]  ? inet_del_offload+0x30/0x30
[  161.954993]  __netif_receive_skb_core+0x84a/0xb30
[  161.956091]  ? process_backlog+0x92/0x120
[  161.957160]  process_backlog+0x92/0x120
[  161.958130]  net_rx_action+0x261/0x3a0
[  161.959103]  __do_softirq+0x104/0x297
[  161.960079]  irq_exit+0xa3/0xb0
[  161.961007]  do_IRQ+0x45/0xc0
[  161.961844]  common_interrupt+0x7a/0x7a
[  161.963109]  </IRQ>
[  161.964560] RIP: 0010:default_idle+0x12/0xf0
[  161.965914] RSP: 0018:ffff9de666857ec0 EFLAGS: 00000246 ORIG_RAX: ffffffffffffffc4
[  161.967915] RAX: ffffffffa8e28510 RBX: ffff9de6663f50c0 RCX: 0000000000000000
[  161.970846] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000000
[  161.972246] RBP: 0000000000000001 R08: 0000000000000002 R09: 0000000000000001
[  161.973648] R10: 00000000ffffc9eb R11: 0000000000000000 R12: ffff9de6663f50c0
[  161.975005] R13: ffff9de6663f50c0 R14: 0000000000000000 R15: 0000000000000000
[  161.976282]  ? __sched_text_end+0x3/0x3
[  161.977184]  do_idle+0x156/0x1b0
[  161.978045]  cpu_startup_entry+0x6a/0x70
[  161.978948]  start_secondary+0x188/0x1b0
[  161.979883]  secondary_startup_64+0xa5/0xb0
[  161.980819] Code: f8 f6 c2 04 0f 84 25 ff ff ff 8b 31 48 83 c0 04 48 83 c1 04 89 70 fc f6 c2 02 0f 84 18 ff ff ff 0f b7 31 48 83 c0 02 48 83 c1 02 <66> 89 70 fe 83 e2 01 74 05 0f b6 11 88 10 c3 66 0f 1f 84 00 00
[  161.985038] RIP: __memcpy_fast+0x148/0x160 [tempesta_lib] RSP: ffff9de67fd03878
[  161.986871] ---[ end trace e55639d14da07e8e ]---
[  161.987974] Kernel panic - not syncing: Fatal exception in interrupt
[  161.989417] Kernel Offset: 0x27800000 from 0xffffffff81000000 (relocation range: 0xffffffff80000000-0xffffffffbfffffff)
[  161.991164] Rebooting in 60 seconds..

[vankoven]

I couldn't reproduce the crash from the message above.

[vankoven]

I also noticed max_misses misbehaviour ....

This was detached into #1397 #1398

[krizhanovsky]

Created separate https://github.com/tempesta-tech/tempesta/issues/1399 for the crash - the bug is hard to reproduce and could be unrelated to this task.