Bug 1204932

A report from a different site with a more complete analysis of the core file (3 different core files available). This core file is with packagekitd from the rpm PackageKit-0.5.8-23.el6.x86_64.rpm.

(gdb) bt
Python Exception <type 'exceptions.ImportError'> No module named gdb.frames:
#0  __pthread_mutex_lock (mutex=0x6c6568723b343667) at pthread_mutex_lock.c:50
#1  0x000000302643f284 in g_main_loop_quit (loop=0x1f422a0) at gmain.c:3327
#2  0x000000302740e3de in g_closure_invoke (closure=0x1f4a570, return_value=0x0, n_param_values=2,
    param_values=0x1f4c560, invocation_hint=0x7fffe70246f0) at gclosure.c:767
#3  0x00000030274248d5 in signal_emit_unlocked_R (node=<optimized out>, detail=0, instance=0x1ee9000,
    emission_return=0x0, instance_and_params=0x1f4c560) at gsignal.c:3252
#4  0x0000003027425d76 in g_signal_emit_valist (instance=<optimized out>, signal_id=<optimized out>,
    detail=<optimized out>, var_args=0x7fffe70248e0) at gsignal.c:2983
#5  0x0000003027426333 in g_signal_emit (instance=<optimized out>, signal_id=<optimized out>, detail=<optimized out>)
    at gsignal.c:3040
#6  0x000000000042169e in pk_backend_finished_delay (data=<optimized out>) at pk-backend.c:1939
#7  0x000000302644108b in g_timeout_dispatch (source=<optimized out>, callback=<optimized out>,
    user_data=<optimized out>) at gmain.c:3893
#8  0x0000003026440642 in g_main_dispatch (context=0x1ee34c0) at gmain.c:2441
#9  g_main_context_dispatch (context=0x1ee34c0) at gmain.c:3014
#10 0x0000003026444c98 in g_main_context_iterate (context=0x1ee34c0, block=1, dispatch=1, self=<optimized out>)
    at gmain.c:3092
#11 0x00000030264451a5 in g_main_loop_run (loop=0x1ee6dd0) at gmain.c:3300
#12 0x000000000040dcd3 in main (argc=1, argv=0x7fffe7024e58) at pk-main.c:336

It's a bad GMainLoop * passed into g_main_loop_quit:

(gdb) frame 1
#1  0x000000302643f284 in g_main_loop_quit (loop=0x1f422a0) at gmain.c:3327
3327    gmain.c: No such file or directory.
(gdb) p *loop
$1 = {context = 0x6c6568723b34365f, is_running = 909670445, ref_count = 758396511}
(gdb) frame 11
#11 0x00000030264451a5 in g_main_loop_run (loop=0x1ee6dd0) at gmain.c:3300
3300    in gmain.c
(gdb) p *loop
$2 = {context = 0x1ee34c0, is_running = 1, ref_count = 2}

Similar values for the GClosure *closure on frame 2:

(gdb) frame 2
#2  0x000000302740e3de in g_closure_invoke (closure=0x1f4a570, return_value=0x0, n_param_values=2,
    param_values=0x1f4c560, invocation_hint=0x7fffe70246f0) at gclosure.c:767
767     gclosure.c: No such file or directory.
(gdb) p *closure
$3 = {ref_count = 2, meta_marshal = 0, n_guards = 0, n_fnotifiers = 0, n_inotifiers = 0, in_inotify = 0,
  floating = 0, derivative_flag = 0, in_marshal = 1, is_invalid = 0,
  marshal = 0x40c140 <g_cclosure_marshal_VOID(unsigned int0_t)@plt>, data = 0x1f015b0, notifiers = 0x0}

(gdb) list  g_closure_invoke
737     g_closure_invoke (GClosure       *closure,
738                       GValue /*out*/ *return_value,
739                       guint           n_param_values,
740                       const GValue   *param_values,
741                       gpointer        invocation_hint)
742     {
743       g_return_if_fail (closure != NULL);
744
745       g_closure_ref (closure);      /* preserve floating flag */
746       if (!closure->is_invalid)
747         {
748           GClosureMarshal marshal;
749           gpointer marshal_data;
750           gboolean in_marshal = closure->in_marshal;
751
752           g_return_if_fail (closure->marshal || closure->meta_marshal);
753
754           SET (closure, in_marshal, TRUE);
755           if (closure->meta_marshal)
756             {
757               marshal_data = closure->notifiers[0].data;
758               marshal = (GClosureMarshal);
759             }
760           else
761             {
762               marshal_data = NULL;
763               marshal = closure->marshal;
764             }
765           if (!in_marshal)
766             closure_invoke_notifiers (closure, PRE_NOTIFY);
767           marshal (closure,
768                    return_value,
769                    n_param_values, param_values,
770                    invocation_hint,
771                    marshal_data);
772           if (!in_marshal)
773             closure_invoke_notifiers (closure, POST_NOTIFY);
774           SET (closure, in_marshal, in_marshal);
775         }
776       g_closure_unref (closure);

This is the same as other core files I've looked at but taking it a step further since closure->meta_marshal should be 0 we should set marshal_data to be NULL and marshal to be <g_cclosure_marshal_VOID(unsigned int0_t)@plt> (the function is actually g_cclosure_marshal_VOID__UINT in the source I believe) so we should have ended up here:

void
g_cclosure_marshal_VOID__UINT (GClosure     *closure,
                               GValue       *return_value G_GNUC_UNUSED,
                               guint         n_param_values,
                               const GValue *param_values,
                               gpointer      invocation_hint G_GNUC_UNUSED,
                               gpointer      marshal_data)
{
  typedef void (*GMarshalFunc_VOID__UINT) (gpointer     data1,
                                           guint        arg_1,
                                           gpointer     data2);
  register GMarshalFunc_VOID__UINT callback;
  register GCClosure *cc = (GCClosure*) closure;
  register gpointer data1, data2;

  g_return_if_fail (n_param_values == 2);

  if (G_CCLOSURE_SWAP_DATA (closure))
    {
      data1 = closure->data;
      data2 = g_value_peek_pointer (param_values + 0);
    }
  else
    {
      data1 = g_value_peek_pointer (param_values + 0);
      data2 = closure->data;
    }
  callback = (GMarshalFunc_VOID__UINT) (marshal_data ? marshal_data : cc->callback);

  callback (data1,
            g_marshal_value_peek_uint (param_values + 1),
            data2);
}

And because marshal_data should be NULL we should have ended up calling pk_transaction_extra_finished_cb:

(gdb) p (GCClosure *)closure
$5 = (GCClosure *) 0x1f4a570
(gdb) p *$5
$6 = {closure = {ref_count = 2, meta_marshal = 0, n_guards = 0, n_fnotifiers = 0, n_inotifiers = 0, in_inotify = 0,
    floating = 0, derivative_flag = 0, in_marshal = 1, is_invalid = 0,
    marshal = 0x40c140 <g_cclosure_marshal_VOID(unsigned int0_t)@plt>, data = 0x1f015b0, notifiers = 0x0},
  callback = 0x420d10 <pk_transaction_extra_finished_cb>}

If we did actually call pk_transaction_extra_finished_cb it can call g_main_loop_quit:

static void
pk_transaction_extra_finished_cb (PkBackend *backend, PkExitEnum exit_enum, PkTransactionExtra *extra)
{
        if (g_main_loop_is_running (extra->priv->loop))
                g_main_loop_quit (extra->priv->loop);
}

If we look at the disassembled output there's no change to rsp so we don't allocate a stack frame and we actually jmpq to the PLT for g_main_loop_quit so this function won't ever appear on the stack (optimisation can be not very nice when it hides stuff like this):

(gdb) disass pk_transaction_extra_finished_cb
Dump of assembler code for function pk_transaction_extra_finished_cb:
   0x0000000000420d10 <+0>:     mov    0x18(%rdx),%rax
   0x0000000000420d14 <+4>:     push   %rbx
   0x0000000000420d15 <+5>:     mov    %rdx,%rbx
   0x0000000000420d18 <+8>:     mov    0x10(%rax),%rdi
   0x0000000000420d1c <+12>:    callq  0x40c110 <g_main_loop_is_running@plt>
   0x0000000000420d21 <+17>:    test   %eax,%eax
   0x0000000000420d23 <+19>:    jne    0x420d30 <pk_transaction_extra_finished_cb+32>
   0x0000000000420d25 <+21>:    pop    %rbx
   0x0000000000420d26 <+22>:    retq
   0x0000000000420d27 <+23>:    nopw   0x0(%rax,%rax,1)
   0x0000000000420d30 <+32>:    mov    0x18(%rbx),%rax
   0x0000000000420d34 <+36>:    pop    %rbx
   0x0000000000420d35 <+37>:    mov    0x10(%rax),%rdi
   0x0000000000420d39 <+41>:    jmpq   0x40c470 <g_main_loop_quit@plt>
End of assembler dump.

It does explain why it appears that g_closure_invoke called g_main_loop_quit when only looking at the stack trace when it didn't actually call it directly. The 3rd argument is closure->data from g_closure_invoke:

(gdb) p (PkTransactionExtra *)0x1f015b0
$7 = (PkTransactionExtra *) 0x1f015b0
(gdb) p *$7
$8 = {parent = {g_type_instance = {g_class = 0x1ee5360}, ref_count = 1, qdata = 0x0}, priv = 0x1f015d0}
(gdb) p *$8->priv
$9 = {db = 0x1f70438, backend = 0x1ee9000, loop = 0x1f422a0, list = 0x1f0b100, lsof = 0x1f22670, proc = 0x1f49c70,
  conf = 0x1ee5630, finished_id = 245, package_id = 246, no_update_process_list = 0x1f70340, hash = 0x1f0c850,
  files_list = 0x1ed5980, pids = 0x1ed58a0}

That gives us the value for loop passed into g_main_loop_quit:

#1  0x000000302643f284 in g_main_loop_quit (loop=0x1f422a0) at gmain.c:3327

And that triggers the core dump:

(gdb) p *$9->loop
$10 = {context = 0x6c6568723b34365f, is_running = 909670445, ref_count = 758396511}

Since context is not a valid pointer to a mutex. So now we can explain how we got to where we died the backtrace now makes sense. So the question is why is loop invalid in that structure?

I've had a look at the code in pk-transaction-extra.c and it seems somewhat racey/dangerous in the way that this happens in multiple places:

        /* wait for finished */
        extra->priv->loop = g_main_loop_new (NULL, FALSE);
        g_main_loop_run (extra->priv->loop);
        g_main_loop_unref (extra->priv->loop);

When this is still registered:

/**
 * pk_transaction_extra_finished_cb:
 **/
static void
pk_transaction_extra_finished_cb (PkBackend *backend, PkExitEnum exit_enum, PkTransactionExtra *extra)
{
        if (g_main_loop_is_running (extra->priv->loop))
                g_main_loop_quit (extra->priv->loop);
}

The loop member of extra->priv only seems to be valid while we are running in g_main_loop_run and if pk_transaction_extra_finished_cb is fired at any time other than when we are in g_main_loop_run the code stands a chance of accessing free memory. The call to g_main_loop_unref frees the variable.

/**
 * g_main_loop_unref:
 * @loop: a #GMainLoop
 *
 * Decreases the reference count on a #GMainLoop object by one. If
 * the result is zero, free the loop and free all associated memory.
 **/
void
g_main_loop_unref (GMainLoop *loop)
{
  g_return_if_fail (loop != NULL);
  g_return_if_fail (g_atomic_int_get (&loop->ref_count) > 0);

  if (!g_atomic_int_dec_and_test (&loop->ref_count))
    return;

  g_main_context_unref (loop->context);
  g_free (loop);
}

Should those places look more like this (it's a bit ugly and there's still a race in that if something triggered pk_transaction_extra_finished_cb before extra->priv->loop was set to NULL we'd still have a chance of having an issue but it's a very small window for a race and given that packagekitd doesn't appear to be threaded a race is unlikely to happen in that window):

        /* wait for finished */
        extra->priv->loop = g_main_loop_new (NULL, FALSE);
        g_main_loop_run (extra->priv->loop);
	GMainLoop *loop=extra->priv->loop;
	extra->priv->loop=NULL;
        g_main_loop_unref (loop);

If something along those lines is done then

gboolean
g_main_loop_is_running (GMainLoop *loop)
{
  g_return_val_if_fail (loop != NULL, FALSE);
  g_return_val_if_fail (g_atomic_int_get (&loop->ref_count) > 0, FALSE);

  return loop->is_running;
}

Will return a fail instead of trying to dereference loop. 

This issue would appear to be a stock standard use after free issue. The only other choice would be to have a data item in one of the structures (e.g. extra->priv) indicating if the loop member was currently valid.

Please fix the issue.

Since you work on gnome issues would it be better (?) if there was another flavour of g_main_loop_unref that accepted a GMainLoop **loop instead of a GMainLoop *loop, for example (this is untested):

void
g_main_loop_dunref (GMainLoop **loop)
{
  GMainLoop *save=*loop;

  g_return_if_fail (save != NULL);
  *loop=NULL;
  g_main_loop_unref(save);
}

Then it would set the callers value of loop to NULL and free the underlying data when you called it (using the packagekitd code as an example) as:

g_main_loop_dunref (&extra->priv->loop)

PackageKit-0.5.8-23 was supposed to fix this issue. We basically disabled most of the PkTransactionExtra code as most of it was unused. Could you perhaps be running with a custom PackageKit.conf file, rather than the vendor-supplied one? 

If you can reproduce this it would be great if you could get a verbose log of "/usr/sbin/packagekitd --verbose" so we can see what's being run. PackageKit is indeed single-threaded so a lot of the races pointed out are pretty hard to hit. I can't actually reproduce this myself on bare metal or in a VM, so I'm a bit confused why it's still happening. Thanks.

There is a packagekitd.log file and update-viewer.log file attached to support case 01322798. The callback pk_transaction_extra_finished_cb is still being armed in the version of packagekitd this issue was reproduced with. I will have to find out if a non-default PackageKit.conf file is in use.

Hello Richard,
 
I attached a file in comment 3 and it includes packagekitd.log file and update-viewer.log (Shane mentioned these in comment 12).

That PackageKit.conf needs to have:

CheckSharedLibrariesInUse=false
UseUpdateCache=false

I'm guessing you can't reproduce the crash with those two set back to the default? Either the customer isn't using the fixed build (which changed the defaults), or for some reason the new PackageKit.conf wasn't replaced during the update (perhaps manually modified).

Richard

(In reply to Richard Hughes from comment #16)
> That PackageKit.conf needs to have:
> 
> CheckSharedLibrariesInUse=false
> UseUpdateCache=false
> 
> I'm guessing you can't reproduce the crash with those two set back to the
> default? Either the customer isn't using the fixed build (which changed the
> defaults), or for some reason the new PackageKit.conf wasn't replaced during
> the update (perhaps manually modified).
> 

I checked the default conf. file included in PackageKit-0.5.8-25.el6 and both the settings are set to True. Also the patch 0001-Do-not-crash-when-running-the-GMainLoop-in-PkTransac.patch doesn't change these values.

BTW I've asked my end customer to retest with:

CheckSharedLibrariesInUse=false
UseUpdateCache=false

In their configuration file to see if that will address the core dumps being seen.

The customer confirmed that changing both of those settings to false stopped the core dumps. What plans are there to actually change the defaults from true (based on comment 17) to false in an errata release?

(In reply to Shane Seymour from comment #21)
> The customer confirmed that changing both of those settings to false stopped
> the core dumps. What plans are there to actually change the defaults from
> true (based on comment 17) to false in an errata release?

This was done in PackageKit-0.5.8-23 -- either the that isn't what's installed or the config file was modified manually and thus not altered when the package was updated.

Richard.

Can you reply comment 17 was it wrong when it says that a later version does not have those changes in it? This is what was said in that comment:

"I checked the default conf. file included in PackageKit-0.5.8-25.el6 and both the settings are set to True. Also the patch 0001-Do-not-crash-when-running-the-GMainLoop-in-PkTransac.patch doesn't change these values."

I went and double checked the rpm and those settings:

$ ll
total 528
-rw-r--r--. 1 shane debuginfo 539620 Aug  3 19:25 PackageKit-0.5.8-23.el6.x86_64.rpm
$ rpm2cpio < PackageKit-0.5.8-23.el6.x86_64.rpm |cpio -i --make-directories
4676 blocks
$ find . -name Pack\*conf
./etc/PackageKit/PackageKit.conf
$ grep CheckSharedLibrariesInUse ./etc/PackageKit/PackageKit.conf
CheckSharedLibrariesInUse=true
$ grep UseUpdateCache ./etc/PackageKit/PackageKit.conf
UseUpdateCache=true

appear to be very much set to true as defaults in the version when you say they are not.

I haven't installed the rpm so there could be something that modifies PackageKit.conf during the install process but the file as it is shipped in PackageKit-0.5.8-23 has both those things set to true and not false.

Can we please get an errata released for this changing the defaults from:

CheckSharedLibrariesInUse=true
UseUpdateCache=true

To:

CheckSharedLibrariesInUse=false
UseUpdateCache=false

So we can get this issue addressed? It's been known that the defaults were not set to false since the end of May (3 months ago) and since then we've gotten confirmation from the end customer that changing them to false resolves this customers issue.

It's now close to 6 months waiting to hear anything about releasing something to change the defaults from:

CheckSharedLibrariesInUse=true
UseUpdateCache=true

To:

CheckSharedLibrariesInUse=false
UseUpdateCache=false

I'd really like to hear something about if this will ever be fixed or not. Next step is to see what I can do about getting this BZ added to the HP blocker list for the next RHEL 6 update release.

(In reply to Shane Seymour from comment #29)
> I'd really like to hear something about if this will ever be fixed or not.
> Next step is to see what I can do about getting this BZ added to the HP
> blocker list for the next RHEL 6 update release.

The bug is going to be fixed in RHEL 6.8 release.

(In reply to Shane Seymour from comment #29)
> It's now close to 6 months waiting to hear anything about releasing
> something to change the defaults from:
> 
> CheckSharedLibrariesInUse=true
> UseUpdateCache=true
> 
> To:
> 
> CheckSharedLibrariesInUse=false
> UseUpdateCache=false

So, I think I've worked out what the issue is. If you do a fresh install with PackageKit-0.5.8-23 (rather than upgrading from a previous release) then the default config file does indeed get set as false,false. As the config file is marked %config(noreplace) in the spec file I'm guessing rpm doesn't overwrite the contents on update, and I had assumed that rpm would only refuse to overwrite a default config file if it had been modified by the user.

For 6.8 I'll ship a different fix that just causes the C code to return false, even if the config file is set to true. This will mean the unused plugin code will be disabled no matter what the config file says.

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://rhn.redhat.com/errata/RHBA-2016-0914.html