search

tempesta-tech / tempesta

All-in-one solution for high performance web content delivery and advanced protection against DDoS and web attacks
https://tempesta-tech.com/
GNU General Public License v2.0
613 stars 103 forks source link

Crash in tfw_sched_hash_del_grp() #794

Closed krizhanovsky closed 7 years ago

krizhanovsky commented 7 years ago

I tested latest version of #783 after benchmark to reproduce #692, so a Tempesta FW instance were running. There are also running Nginx in proxy mode and Apache HTTPD on the same host with Tempesta FW, so configuration is

    Client -> Tempesta FW -> Nginx -> Apache HTTPD

There were no traffic load when I started the test. The test has stuck, so I had to interrupt it with SIGTERM:

    # ./run_tests.py 

    ----------------------------------------------------------------------
    Running functional tests...
    ----------------------------------------------------------------------

    E.^C^C^CTraceback (most recent call last):
      File "./run_tests.py", line 101, in <module>
        testRunner.run(tests)
      File "/usr/lib/python2.7/unittest/runner.py", line 151, in run
        test(result)
      File "/usr/lib/python2.7/unittest/suite.py", line 70, in __call__
        return self.run(*args, **kwds)
      File "/usr/lib/python2.7/unittest/suite.py", line 108, in run
        test(result)
      File "/usr/lib/python2.7/unittest/suite.py", line 70, in __call__
        return self.run(*args, **kwds)
      File "/usr/lib/python2.7/unittest/suite.py", line 108, in run
        test(result)
      File "/usr/lib/python2.7/unittest/suite.py", line 70, in __call__
        return self.run(*args, **kwds)
      File "/usr/lib/python2.7/unittest/suite.py", line 108, in run
        test(result)
      File "/usr/lib/python2.7/unittest/case.py", line 393, in __call__
        return self.run(*args, **kwds)
      File "/usr/lib/python2.7/unittest/case.py", line 358, in run
        self.tearDown()
      File "/root/tempesta.759/tempesta_fw/t/functional/testers/functional.py", line 62, in tearDown
        self.tempesta.stop()
      File "/root/tempesta.759/tempesta_fw/t/functional/helpers/control.py", line 266, in stop
        self.node.run_cmd(cmd, timeout=30, err_msg=(self.err_msg % 'stop'))
      File "/root/tempesta.759/tempesta_fw/t/functional/helpers/remote.py", line 74, in run_cmd
        error.bug(err_msg, stdout=stdout, stderr=stderr)
      File "/usr/lib/python2.7/dist-packages/subprocess32.py", line 867, in __exit__
        self.wait()
      File "/usr/lib/python2.7/dist-packages/subprocess32.py", line 1692, in wait
        (pid, sts) = self._try_wait(0)
      File "/usr/lib/python2.7/dist-packages/subprocess32.py", line 1639, in _try_wait
        (pid, sts) = _eintr_retry_call(os.waitpid, self.pid, wait_flags)
      File "/usr/lib/python2.7/dist-packages/subprocess32.py", line 546, in _eintr_retry_call
        return func(*args)
      File "/usr/lib/python2.7/unittest/signals.py", line 36, in __call__
        self.default_handler(signum, frame)
    KeyboardInterrupt

And the kernel module crashed with (there are all Tempesta FW start/stop messages just after OS booting messages):

    Debian GNU/Linux 9 debian ttyS0

    debian login: [  676.729507] perf: Dynamic interrupt throttling disabled, can hang your system!
    [  676.781541] tempesta_tls: loading out-of-tree module taints kernel.
    [  676.873618] [tdb] Start Tempesta DB
    [  676.902065] [tempesta] Initializing Tempesta FW kernel module...
    [  676.957342] [tempesta] Registering new scheduler: hash
    [  676.966590] [tempesta] Registering new scheduler: http
    [  676.978375] [tempesta] Registering new scheduler: ratio
    [  677.001332] [tempesta] Starting all modules...
    [  677.025723] [tdb] Opened table /opt/tempesta/db/filter.tdb: size=16777216 rec_size=20 base=ffff9797f9c00000
    [  677.027604] [tempesta] Open listen socket on: 192.168.100.4
    [  677.028325] [tempesta] modules are started
    [  688.491493] TCP: request_sock_TCP: Possible SYN flooding on port 80. Sending cookies.  Check SNMP counters.
    [  790.022726] INFO: NMI handler (perf_event_nmi_handler) took too long to run: 1.876 msecs
    [ 1948.431976] INFO: NMI handler (perf_event_nmi_handler) took too long to run: 2.962 msecs
    [ 4328.848026] INFO: NMI handler (perf_event_nmi_handler) took too long to run: 3.103 msecs
    [ 6218.580016] INFO: NMI handler (perf_event_nmi_handler) took too long to run: 11.782 msecs
    [ 8629.167427] clocksource: timekeeping watchdog on CPU2: Marking clocksource 'tsc' as unstable because the skew is too large:
    [ 8629.182417] clocksource:                       'hpet' wd_now: f3b8dee1 wd_last: df196030 mask: ffffffff
    [ 8629.191103] clocksource:                       'tsc' cs_now: 146abc596b86 cs_last: 1469921eb44c mask: ffffffffffffffff
    [ 8629.247945] clocksource: Switched to clocksource hpet
    [ 8638.540109] hrtimer: interrupt took 13806662 ns
    [15858.319572] [tempesta] Stopping all modules...
    [15858.587558] [tdb] Close table 'filter0.tdb'
    [15858.598926] [tempesta] Un-registering scheduler: hash
    [15858.667485] [tempesta] Un-registering scheduler: http
    [15858.740703] [tempesta] Un-registering scheduler: ratio
    [15858.810191] [tempesta] exiting...
    [15858.907857] [tdb] Shutdown Tempesta DB
    [15859.186311] [tdb] Start Tempesta DB
    [15859.208670] [tempesta] Initializing Tempesta FW kernel module...
    [15859.245681] [tempesta] Registering new scheduler: hash
    [15859.250015] [tempesta] Registering new scheduler: http
    [15859.258976] [tempesta] Registering new scheduler: ratio
    [15859.284555] [tempesta] Starting all modules...
    [15859.313007] [tdb] Opened table /opt/tempesta/db/filter.tdb: size=16777216 rec_size=20 base=ffff9797f9c00000
    [15859.490309] [tdb] Close table 'filter0.tdb'
    [15859.832823] [tdb] Shutdown Tempesta DB
    [15860.127659] [tdb] Start Tempesta DB
    [15860.252779] [tdb] Opened table /opt/tempesta/db/filter.tdb: size=16777216 rec_size=20 base=ffff9797f9c00000
    [15860.635197] [tdb] Close table 'filter0.tdb'
    [15860.636281] general protection fault: 0000 [#1] SMP DEBUG_PAGEALLOC
    [15860.637228] Modules linked in: tfw_sched_ratio(O) tfw_sched_http(O) tfw_sched_hash(O) tempesta_fw(O) tempesta_db(O) tempesta_tls(O) crct10dif_pclmul crc32_pclmul ghash_clmulni_intel aesni_intel aes_x86_64 lrw gf128mul glue_helper ablk_helper cryptd bochs_drm ttm drm_kms_helper drm ppdev fb_sys_fops syscopyarea sg sysfillrect sysimgblt parport_pc serio_raw parport pcspkr button ip_tables x_tables autofs4 ext4 crc16 jbd2 fscrypto mbcache sr_mod sd_mod cdrom ata_generic ata_piix libata scsi_mod crc32c_intel psmouse e1000 i2c_piix4 [last unloaded: tempesta_tls]
    [15860.640072] CPU: 3 PID: 3863 Comm: sysctl Tainted: G           O    4.9.35 #23
    [15860.640072] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.9.1-1.fc24 04/01/2014
    [15860.640072] task: ffff9797dfae86c0 task.stack: ffffb06180c38000
    [15860.640072] RIP: 0010:[<ffffffffc05d301d>]  [<ffffffffc05d301d>] tfw_sched_hash_del_grp+0x1d/0x60 [tfw_sched_hash]
    [15860.640072] RSP: 0018:ffffb06180c3bcd8  EFLAGS: 00010292
    [15860.640072] RAX: 6b6b6b6b6b6b6b03 RBX: ffff9797e560eb40 RCX: ffff9797e560eb50
    [15860.640072] RDX: 6b6b6b6b6b6b6b6b RSI: ffff9797dfae8e18 RDI: ffff9797e560eb40
    [15860.640072] RBP: ffffb06180c3bce8 R08: d84156c5635688c0 R09: ffff97985a493cf0
    [15860.640072] R10: 0000000000000000 R11: 0000000000000000 R12: ffff9797e560eb50
    [15860.640072] R13: ffff9797e560eb40 R14: ffffffffc073ea80 R15: ffffb06180c3bf18
    [15860.640072] FS:  00007f414c4f8880(0000) GS:ffff9797ff380000(0000) knlGS:0000000000000000
    [15860.640072] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
    [15860.640072] CR2: 00007f414bbf2d00 CR3: 00000001256e0000 CR4: 00000000003406e0
    [15860.640072] Stack:
    [15860.640072]  0000000000000286 ffff9797da493cf8 ffffb06180c3bd18 ffffffffc0727827
    [15860.640072]  ffffffffc073f0d8 ffffffffc073f0d8 ffffffffc073e6a0 000055741f6282e0
    [15860.640072]  ffffb06180c3bd38 ffffffffc072b463 ffffffffc073ec00 ffffffffc073ebc0
    [15860.640072] Call Trace:
    [15860.640072]  [<ffffffffc0727827>] tfw_sg_release_all+0x67/0xa0 [tempesta_fw]
    [15860.640072]  [<ffffffffc072b463>] tfw_clean_srv_groups+0xf3/0x100 [tempesta_fw]
    [15860.640072]  [<ffffffffc0709da1>] tfw_cfg_stop+0x71/0xb0 [tempesta_fw]
    [15860.640072]  [<ffffffffc0725f8f>] handle_sysctl_state_io+0x19f/0x1d0 [tempesta_fw]
    [15860.640072]  [<ffffffffc0725e2c>] ? handle_sysctl_state_io+0x3c/0x1d0 [tempesta_fw]
    [15860.640072]  [<ffffffff95e697a4>] ? ns_capable_common+0x34/0x90
    [15860.640072]  [<ffffffff9604c895>] proc_sys_call_handler+0xe5/0x100
    [15860.640072]  [<ffffffff9604c8bf>] proc_sys_write+0xf/0x20
    [15860.640072]  [<ffffffff95fc8b92>] __vfs_write+0x32/0x160
    [15860.640072]  [<ffffffff95ec9f23>] ? rcu_read_lock_sched_held+0x53/0x60
    [15860.640072]  [<ffffffff95eca22a>] ? rcu_sync_lockdep_assert+0x2a/0x50
    [15860.640072]  [<ffffffff95fcd1dd>] ? __sb_start_write+0xad/0x1a0
    [15860.640072]  [<ffffffff95fc9f98>] ? vfs_write+0x178/0x190
    [15860.640072]  [<ffffffff95fc9ed0>] vfs_write+0xb0/0x190
    [15860.640072]  [<ffffffff95fcb2f3>] SyS_write+0x53/0xc0
    [15860.640072]  [<ffffffff963dd3ae>] entry_SYSCALL_64_fastpath+0x1c/0xb1
    [15860.640072] Code: <48> 8b 50 68 48 c7 80 80 00 00 00 00 00 00 00 48 39 d1 48 8d 42 98 
    [15860.640072] RIP  [<ffffffffc05d301d>] tfw_sched_hash_del_grp+0x1d/0x60 [tfw_sched_hash]
    [15860.640072]  RSP <ffffb06180c3bcd8>
    [15860.681778] ---[ end trace ee8b1cc95b821290 ]---
    [15860.885499] Slab corruption (Tainted: G      D    O   ): tfw_srv_cache start=ffff9797da493cf8, len=160
    [15860.887137] Redzone: 0x9f911029d74e35b/0x9f911029d74e35b
    [15860.888226] Last user: [<ffffffffc0727418>](tfw_server_destroy+0x28/0x40 [tempesta_fw])
    [15860.889454] 080: 00 00 00 00 00 00 00 00 6b 6b 6b 6b 6b 6b 6b 6b  ........kkkkkkkk
    [15860.890617] Prev obj: start=ffff9797da493c40, len=160
    [15860.891506] Redzone: 0x9f911029d74e35b/0x9f911029d74e35b
    [15860.892494] Last user: [<          (null)>](          (null))
    [15860.893520] 000: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b  kkkkkkkkkkkkkkkk
    [15860.894600] 010: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b  kkkkkkkkkkkkkkkk
    [15860.895912] Next obj: start=ffff9797da493db0, len=160
    [15860.897282] Redzone: 0x9f911029d74e35b/0x9f911029d74e35b
    [15860.898493] Last user: [<          (null)>](          (null))
    [15860.899402] 000: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b  kkkkkkkkkkkkkkkk
    [15860.900530] 010: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b  kkkkkkkkkkkkkkkk

Note that initially loaded and tested versions of Tempesta FW are essentially different builds. Disassembled tfw_sched_hash_del_grp() is show at the below:

0000000000000000 <tfw_sched_hash_del_grp>:
   0:   55                      push   %rbp
   1:   48 8d 4f 10             lea    0x10(%rdi),%rcx
   5:   48 89 e5                mov    %rsp,%rbp
   8:   53                      push   %rbx
   9:   48 89 fb                mov    %rdi,%rbx
   c:   48 83 ec 08             sub    $0x8,%rsp
  10:   48 8b 57 10             mov    0x10(%rdi),%rdx
  14:   48 39 d1                cmp    %rdx,%rcx
  17:   48 8d 42 98             lea    -0x68(%rdx),%rax
  1b:   74 18                   je     35 <tfw_sched_hash_del_grp+0x35>
  1d:   48 8b 50 68             mov    0x68(%rax),%rdx
  21:   48 c7 80 80 00 00 00    movq   $0x0,0x80(%rax)
  28:   00 00 00 00 
  2c:   48 39 d1                cmp    %rdx,%rcx
  2f:   48 8d 42 98             lea    -0x68(%rdx),%rax
  33:   75 e8                   jne    1d <tfw_sched_hash_del_grp+0x1d>
  35:   48 8b 7b 60             mov    0x60(%rbx),%rdi
  39:   48 85 ff                test   %rdi,%rdi
  3c:   74 0d                   je     4b <tfw_sched_hash_del_grp+0x4b>
  3e:   e8 00 00 00 00          callq  43 <tfw_sched_hash_del_grp+0x43>
                        3f: R_X86_64_PC32       kfree-0x4
  43:   48 c7 43 60 00 00 00    movq   $0x0,0x60(%rbx)
  4a:   00 
  4b:   48 83 c4 08             add    $0x8,%rsp
  4f:   5b                      pop    %rbx
  50:   5d                      pop    %rbp
  51:   c3                      retq
  52:   0f 1f 40 00             nopl   0x0(%rax)
  56:   66 2e 0f 1f 84 00 00    nopw   %cs:0x0(%rax,%rax,1)
  5d:   00 00 00
krizhanovsky commented 7 years ago

Just reproduce it again on clean (restarted machine):

root@debian:~/tempesta.759/tempesta_fw/t/functional# ./run_tests.py

----------------------------------------------------------------------
Running functional tests...
----------------------------------------------------------------------

test_scheduler (sched.test_http.HttpRules) ... ok
test_scheduler (sched.test_http.HttpRulesBackupServers) ... ok
test_hash_scheduler (sched.test_hash_func.HashSchedulerFailoveredTest) ...

Tests config:

# cat tests_config.ini
[Client]
ip = 127.0.0.1
hostname = localhost
ab = ab
wrk = wrk
workdir = /tmp/client

[Tempesta]
workdir = /root/tempesta.759
ip = 127.0.0.1
hostname = localhost
user = root
config = /tmp/tempesta.conf
port = 22

[Server]
workdir = /tmp/nginx
ip = 127.0.0.1
hostname = localhost
nginx = nginx
user = root
port = 22
resources = /var/www/html/

[General]
duration = 10
concurrent_connections = 10
verbose = 1
vankoven commented 7 years ago

@keshonok has found the issue reason: in https://github.com/tempesta-tech/tempesta/blob/master/tempesta_fw/sched/tfw_sched_hash.c#L235 we iterate over the list of already destroyed and freed servers. The list itself is wasn't cleared or nulled, so we work with already freed memory in the cycle.

TfwServer knows nothing about how to free it's sched_data field, so scheduler must be unbound from server group before servers will be destroyed.

aleksostapenko commented 7 years ago

Fixed in 825f006