Uploaded image for project: 'RHEL'
  1. RHEL
  2. RHEL-4084

setroubleshootd crashes when ffi closure cannot execute

Details

    • Bug
    • Resolution: Won't Do
    • Major
    • None
    • rhel-8.2.0
    • pygobject3
    • Major
    • sst_desktop
    • ssg_desktop
    • False
    • Hide

      None

      Show
      None
    • If docs needed, set a value

    Description

      Description of problem:

      On customer's systems running latest packages for RHEL8.2 experience Python crashing 100% of the time when executing setroubleshootd.
      Core dump analysis shows that it crashes due to GLib callback executing dereferencing a NULL pointer:
      -------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------
      Core was generated by `/usr/libexec/platform-python -Es /usr/sbin/setroubleshootd -f '.
      Program terminated with signal SIGSEGV, Segmentation fault.
      #0 g_callable_info_free_closure (callable_info=0x55fc1fcf02d0, closure=0x0)
      at girepository/girffi.c:426
      426 g_free (wrapper->ffi_closure.cif->arg_types);
      [Current thread is 1 (Thread 0x7f584fde6740 (LWP 322982))]
      (gdb) bt
      #0 0x00007f584bb85814 in g_callable_info_free_closure (callable_info=0x55fc1fcf02d0, closure=0x0) at girepository/girffi.c:426
      #1 0x00007f584bdd6b94 in _pygi_invoke_closure_free (data=0x55fc1fcefa80) at pygi-closure.c:638
      #2 0x00007f584b652013 in g_source_callback_unref (cb_data=0x55fc25460090) at gmain.c:1546
      #3 0x00007f584b652013 in g_source_callback_unref (cb_data=0x55fc25460090) at gmain.c:1539
      #4 0x00007f584b653824 in g_source_destroy_internal (source=0x55fc22a85170, context=0x55fc2299d6c0, have_lock=1) at gmain.c:1236
      #5 0x00007f584b655728 in g_main_dispatch (context=0x55fc2299d6c0) at gmain.c:3200
      #6 0x00007f584b655728 in g_main_context_dispatch (context=context@entry=0x55fc2299d6c0) at gmain.c:3829
      #7 0x00007f584b655a48 in g_main_context_iterate (context=0x55fc2299d6c0, block=block@entry=1, dispatch=dispatch@entry=1, self=<optimized out>) at gmain.c:3902
      #8 0x00007f584b655d72 in g_main_loop_run (loop=0x55fc2545f520) at gmain.c:4098
      #9 0x00007f584b40504e in ffi_call_unix64 () at ../src/x86/unix64.S:76
      #10 0x00007f584b404a0f in ffi_call (cif=cif@entry=0x55fc2546e458, fn=<optimized out>, rvalue=<optimized out>, rvalue@entry=0x7fff451e4f38, avalue=<optimized out>) at ../src/x86/ffi64.c:525
      #11 0x00007f584bdd9425 in pygi_invoke_c_callable (function_cache=0x55fc2546e3b0, state=<optimized out>, py_args=<optimized out>, py_kwargs=<optimized out>) at pygi-invoke.c:691
      #12 0x00007f584bddaf3c in pygi_function_cache_invoke (function_cache=<optimized out>, py_args=py_args@entry=(<MainLoop at remote 0x7f583e11aa08>,), py_kwargs=py_kwargs@entry=0x0) at pygi-cache.c:863
      #13 0x00007f584bdd9b4c in pygi_callable_info_invoke
      (info=<optimized out>, py_args=py_args@entry=(<MainLoop at remote 0x7f583e11aa08>,), kwargs=kwargs@entry=0x0, cache=<optimized out>, user_data=user_data@entry=0x0) at pygi-invoke.c:734
      #14 0x00007f584bdd9b83 in _wrap_g_callable_info_invoke (self=<optimized out>, py_args=py_args@entry=(<MainLoop at remote 0x7f583e11aa08>,), kwargs=kwargs@entry=0x0) at pygi-invoke.c:771
      #15 0x00007f584bdce973 in _callable_info_call (self=0x7f583e120928, args=(), kwargs=0x0) at pygi-info.c:561
      #16 0x00007f584f2b9bfc in _PyObject_FastCallDict (func=<gi.FunctionInfo at remote 0x7f583e120928>, args=0x55fc2547a1b8, nargs=<optimized out>, kwargs=0x0)
      at /usr/src/debug/python3-3.6.8-23.el8.x86_64/Objects/abstract.c:2313
      [...]
      #34 0x00007f584f2942ee in run_file (p_cf=0x7fff451e59fc, filename=0x55fc1fadce30 L"/usr/sbin/setroubleshootd", fp=0x55fc1fadc360) at /usr/src/debug/python3-3.6.8-23.el8.x86_64/Modules/main.c:344
      #35 0x00007f584f2942ee in Py_Main (argc=<optimized out>, argv=0x55fc1fadc2a0) at /usr/src/debug/python3-3.6.8-23.el8.x86_64/Modules/main.c:814
      #36 0x000055fc1e0d0b96 in main (argc=5, argv=<optimized out>) at /usr/src/debug/python3-3.6.8-23.el8.x86_64/Programs/python.c:102

      (gdb) p wrapper
      $1 = (GIClosureWrapper *) 0x0

      (gdb) info symbol g_callable_info_free_closure
      g_callable_info_free_closure in section .text of /lib64/libgirepository-1.0.so.1

      (gdb)
      -------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------

      We have wrapper being NULL, so dereferencing fails ...
      The "wrapper" comes from frame 1 ("invoke_closure->closure") which is NULL here (this isn't expected at all).

      Stracing client tool "sealert" and server tool "setroubleshootd" which both execute GLib internally, I can see the following checking when "GLib.py" and "GLib.cpython-36.pyc" are used):

      sealert:
      -------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------
      1140907 08:23:05.819605 stat("/usr/lib64/python3.6/site-packages/gi/overrides/GLib.py",

      {st_dev=makedev(253, 2), st_ino=17246829, st_mode=S_IFREG|0644, st_nlink=1, st_uid=0, st_gid=0, st_blksize=4096, st_blocks=64, st_size=30093, st_atime=1598248902 /* 2020-08-24T01:01:42.361343008-0500 */, st_atime_nsec=361343008, st_mtime=1534094777 /* 2018-08-12T12:26:17-0500 */, st_mtime_nsec=0, st_ctime=1581368844 /* 2020-02-10T15:07:24.765005379-0600 */, st_ctime_nsec=765005379}

      ) = 0 <0.000012>
      1140907 08:23:05.819792 stat("/usr/lib64/python3.6/site-packages/gi/overrides/GLib.py",

      {st_dev=makedev(253, 2), st_ino=17246829, st_mode=S_IFREG|0644, st_nlink=1, st_uid=0, st_gid=0, st_blksize=4096, st_blocks=64, st_size=30093, st_atime=1598248902 /* 2020-08-24T01:01:42.361343008-0500 */, st_atime_nsec=361343008, st_mtime=1534094777 /* 2018-08-12T12:26:17-0500 */, st_mtime_nsec=0, st_ctime=1581368844 /* 2020-02-10T15:07:24.765005379-0600 */, st_ctime_nsec=765005379}

      ) = 0 <0.000011>
      1140907 08:23:05.819906 stat("/usr/lib64/python3.6/site-packages/gi/overrides/GLib.py",

      {st_dev=makedev(253, 2), st_ino=17246829, st_mode=S_IFREG|0644, st_nlink=1, st_uid=0, st_gid=0, st_blksize=4096, st_blocks=64, st_size=30093, st_atime=1598248902 /* 2020-08-24T01:01:42.361343008-0500 */, st_atime_nsec=361343008, st_mtime=1534094777 /* 2018-08-12T12:26:17-0500 */, st_mtime_nsec=0, st_ctime=1581368844 /* 2020-02-10T15:07:24.765005379-0600 */, st_ctime_nsec=765005379}

      ) = 0 <0.000011>

      1140907 08:23:05.819975 openat(AT_FDCWD, "/usr/lib64/python3.6/site-packages/gi/overrides/_pycache/GLib.cpython-36.pyc", O_RDONLY|O_CLOEXEC) = 3</usr/lib64/python3.6/site-packages/gi/overrides/pycache_/GLib.cpython-36.pyc> <0.006222>

      1140907 08:23:05.826259 fstat(3</usr/lib64/python3.6/site-packages/gi/overrides/_pycache_/GLib.cpython-36.pyc>,

      {st_dev=makedev(253, 2), st_ino=25727846, st_mode=S_IFREG|0644, st_nlink=1, st_uid=0, st_gid=0, st_blksize=4096, st_blocks=48, st_size=23091, st_atime=1598248866 /* 2020-08-24T01:01:06.915509494-0500 */, st_atime_nsec=915509494, st_mtime=1534094795 /* 2018-08-12T12:26:35-0500 */, st_mtime_nsec=0, st_ctime=1581368844 /* 2020-02-10T15:07:24.773005380-0600 */, st_ctime_nsec=773005380}

      ) = 0 <0.000009>

      1140907 08:23:05.826343 lseek(3</usr/lib64/python3.6/site-packages/gi/overrides/_pycache_/GLib.cpython-36.pyc>, 0, SEEK_CUR) = 0 <0.000009>
      1140907 08:23:05.826393 fstat(3</usr/lib64/python3.6/site-packages/gi/overrides/_pycache_/GLib.cpython-36.pyc>,

      {st_dev=makedev(253, 2), st_ino=25727846, st_mode=S_IFREG|0644, st_nlink=1, st_uid=0, st_gid=0, st_blksize=4096, st_blocks=48, st_size=23091, st_atime=1598248866 /* 2020-08-24T01:01:06.915509494-0500 */, st_atime_nsec=915509494, st_mtime=1534094795 /* 2018-08-12T12:26:35-0500 */, st_mtime_nsec=0, st_ctime=1581368844 /* 2020-02-10T15:07:24.773005380-0600 */, st_ctime_nsec=773005380}

      ) = 0 <0.000009>
      1140907 08:23:05.826459 read(3</usr/lib64/python3.6/site-packages/gi/overrides/_pycache_/GLib.cpython-36.pyc>, ..., 23092) = 23091 <0.000021>
      1140907 08:23:05.826567 read(3</usr/lib64/python3.6/site-packages/gi/overrides/_pycache_/GLib.cpython-36.pyc>, "", 1) = 0 <0.000009>
      1140907 08:23:05.826621 close(3</usr/lib64/python3.6/site-packages/gi/overrides/_pycache_/GLib.cpython-36.pyc>) = 0 <0.000017>
      -------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------

      Here we see that GLib.py is stat'ed to see if it's older than compiled GLib.cpython-36.pyc code. Since it's older, it uses the compiled code.

      setroubleshootd:
      -------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------
      1140911 08:23:07.385134 stat("/usr/lib64/python3.6/site-packages/gi/overrides/GLib.py",

      {st_dev=makedev(253, 2), st_ino=17246829, st_mode=S_IFREG|0644, st_nlink=1, st_uid=0, st_gid=0, st_blksize=4096, st_blocks=64, st_size=30093, st_atime=1598248902 /* 2020-08-24T01:01:42.361343008-0500 */, st_atime_nsec=361343008, st_mtime=1534094777 /* 2018-08-12T12:26:17-0500 */, st_mtime_nsec=0, st_ctime=1581368844 /* 2020-02-10T15:07:24.765005379-0600 */, st_ctime_nsec=765005379}

      ) = 0 <0.000025>
      1140911 08:23:07.385362 stat("/usr/lib64/python3.6/site-packages/gi/overrides/GLib.py",

      {st_dev=makedev(253, 2), st_ino=17246829, st_mode=S_IFREG|0644, st_nlink=1, st_uid=0, st_gid=0, st_blksize=4096, st_blocks=64, st_size=30093, st_atime=1598248902 /* 2020-08-24T01:01:42.361343008-0500 */, st_atime_nsec=361343008, st_mtime=1534094777 /* 2018-08-12T12:26:17-0500 */, st_mtime_nsec=0, st_ctime=1581368844 /* 2020-02-10T15:07:24.765005379-0600 */, st_ctime_nsec=765005379}

      ) = 0 <0.000024>
      1140911 08:23:07.385496 stat("/usr/lib64/python3.6/site-packages/gi/overrides/GLib.py",

      {st_dev=makedev(253, 2), st_ino=17246829, st_mode=S_IFREG|0644, st_nlink=1, st_uid=0, st_gid=0, st_blksize=4096, st_blocks=64, st_size=30093, st_atime=1598248902 /* 2020-08-24T01:01:42.361343008-0500 */, st_atime_nsec=361343008, st_mtime=1534094777 /* 2018-08-12T12:26:17-0500 */, st_mtime_nsec=0, st_ctime=1581368844 /* 2020-02-10T15:07:24.765005379-0600 */, st_ctime_nsec=765005379}

      ) = 0 <0.000024>

      1140911 08:23:07.385584 openat(AT_FDCWD, "/usr/lib64/python3.6/site-packages/gi/overrides/_pycache/GLib.cpython-36.pyc", O_RDONLY|O_CLOEXEC) = 3</usr/lib64/python3.6/site-packages/gi/overrides/pycache_/GLib.cpython-36.pyc> <0.000038>

      1140911 08:23:07.385671 fstat(3</usr/lib64/python3.6/site-packages/gi/overrides/_pycache_/GLib.cpython-36.pyc>,

      {st_dev=makedev(253, 2), st_ino=25727846, st_mode=S_IFREG|0644, st_nlink=1, st_uid=0, st_gid=0, st_blksize=4096, st_blocks=48, st_size=23091, st_atime=1598248866 /* 2020-08-24T01:01:06.915509494-0500 */, st_atime_nsec=915509494, st_mtime=1534094795 /* 2018-08-12T12:26:35-0500 */, st_mtime_nsec=0, st_ctime=1581368844 /* 2020-02-10T15:07:24.773005380-0600 */, st_ctime_nsec=773005380}

      ) = 0 <0.000020>

      1140911 08:23:07.385752 lseek(3</usr/lib64/python3.6/site-packages/gi/overrides/_pycache_/GLib.cpython-36.pyc>, 0, SEEK_CUR) = 0 <0.000015>
      1140911 08:23:07.385810 fstat(3</usr/lib64/python3.6/site-packages/gi/overrides/_pycache_/GLib.cpython-36.pyc>,

      {st_dev=makedev(253, 2), st_ino=25727846, st_mode=S_IFREG|0644, st_nlink=1, st_uid=0, st_gid=0, st_blksize=4096, st_blocks=48, st_size=23091, st_atime=1598248866 /* 2020-08-24T01:01:06.915509494-0500 */, st_atime_nsec=915509494, st_mtime=1534094795 /* 2018-08-12T12:26:35-0500 */, st_mtime_nsec=0, st_ctime=1581368844 /* 2020-02-10T15:07:24.773005380-0600 */, st_ctime_nsec=773005380}

      ) = 0 <0.000020>
      1140911 08:23:07.385891 read(3</usr/lib64/python3.6/site-packages/gi/overrides/_pycache_/GLib.cpython-36.pyc>, ..., 23092) = 23091 <0.000036>
      1140911 08:23:07.386007 read(3</usr/lib64/python3.6/site-packages/gi/overrides/_pycache_/GLib.cpython-36.pyc>, "", 1) = 0 <0.000020>
      1140911 08:23:07.386080 close(3</usr/lib64/python3.6/site-packages/gi/overrides/_pycache_/GLib.cpython-36.pyc>) = 0 <0.000028>

      STAT ON GLib.py AGAIN:
      1140911 08:23:09.232603 stat("/usr/lib64/python3.6/site-packages/gi/overrides/GLib.py",

      {st_dev=makedev(253, 2), st_ino=17246829, st_mode=S_IFREG|0644, st_nlink=1, st_uid=0, st_gid=0, st_blksize=4096, st_blocks=64, st_size=30093, st_atime=1598248902 /* 2020-08-24T01:01:42.361343008-0500 */, st_atime_nsec=361343008, st_mtime=1534094777 /* 2018-08-12T12:26:17-0500 */, st_mtime_nsec=0, st_ctime=1581368844 /* 2020-02-10T15:07:24.765005379-0600 */, st_ctime_nsec=765005379}

      ) = 0 <0.000014>

      1140911 08:23:09.232681 openat(AT_FDCWD, "/usr/lib64/python3.6/site-packages/gi/overrides/GLib.py", O_RDONLY|O_CLOEXEC) = 9</usr/lib64/python3.6/site-packages/gi/overrides/GLib.py> <0.004274>
      1140911 08:23:09.237015 fstat(9</usr/lib64/python3.6/site-packages/gi/overrides/GLib.py>,

      {st_dev=makedev(253, 2), st_ino=17246829, st_mode=S_IFREG|0644, st_nlink=1, st_uid=0, st_gid=0, st_blksize=4096, st_blocks=64, st_size=30093, st_atime=1598248902 /* 2020-08-24T01:01:42.361343008-0500 */, st_atime_nsec=361343008, st_mtime=1534094777 /* 2018-08-12T12:26:17-0500 */, st_mtime_nsec=0, st_ctime=1581368844 /* 2020-02-10T15:07:24.765005379-0600 */, st_ctime_nsec=765005379}

      ) = 0 <0.000008>
      1140911 08:23:09.237091 ioctl(9</usr/lib64/python3.6/site-packages/gi/overrides/GLib.py>, TCGETS, 0x7ffd6ce70db0) = -1 ENOTTY (Inappropriate ioctl for device) <0.000008>
      1140911 08:23:09.237143 lseek(9</usr/lib64/python3.6/site-packages/gi/overrides/GLib.py>, 0, SEEK_CUR) = 0 <0.000007>
      1140911 08:23:09.237188 read(9</usr/lib64/python3.6/site-packages/gi/overrides/GLib.py>, ..., 4096) = 4096 <0.000008>
      ...
      1140911 08:23:09.237751 read(9</usr/lib64/python3.6/site-packages/gi/overrides/GLib.py>, "", 8192) = 0 <0.000007>
      1140911 08:23:09.237793 close(9</usr/lib64/python3.6/site-packages/gi/overrides/GLib.py>) = 0 <0.000014>
      1140911 08:23:09.237856 write(4<anon_inode:[eventfd]>, "\1\0\0\0\0\0\0\0", 8) = 8 <0.000009>
      1140911 08:23:09.237895 — SIGSEGV

      {si_signo=SIGSEGV, si_code=SEGV_MAPERR, si_addr=0x18}

      -------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------

      Here we see that setroubleshootd also stats GLib.py and starts using compiled GLib.cpython-36.pyc code.
      However, later we see GLib.py is read for some unknown reason even though the last "stat()" at timestamp 08:23:09.232603 (see "STAT ON GLib.py AGAIN" token above) is identical to all other stats, hence there is no modification of GLib.py that could explain Python "decides" to read it now and stop using GLib.cpython-36.pyc code.

      My assumption is that something in Python implementation makes it believe the file changed, sources it again, which makes the pending objects in memory still referencing compiled code become dangling and causing the SEGV when the GLib callback is called.

      Version-Release number of selected component (if applicable):

      platform-python-3.6.8-23.el8.x86_64

      How reproducible:

      ALWAYS on customer site, on all of his RHEL8 systems, I'm not managing to reproduce at all.

      Steps to Reproduce:
      1. Execute "sealert -l *"

      Actual results:

      setroubleshootd crashes

      Attachments

        Activity

          People

            klember@redhat.com Kalev Lember
            rhn-support-rmetrich Renaud Metrich
            Kalev Lember Kalev Lember
            Desktop QE Desktop QE
            Votes:
            0 Vote for this issue
            Watchers:
            12 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved: