Bug 1253318

Summary: [abrt] [beaker] [master] Error sending message: The connection is closed
Product: Red Hat Enterprise Linux 7 Reporter: Lubomir Rintel <lrintel>
Component: NetworkManagerAssignee: Rashid Khan <rkhan>
Status: CLOSED NOTABUG QA Contact: Desktop QE <desktop-qa-list>
Severity: medium Docs Contact:
Priority: medium    
Version: 7.3CC: danw, dcbw, jklimes, lrintel, rkhan, thaller
Target Milestone: rc   
Target Release: ---   
Hardware: x86_64   
OS: Unspecified   
Whiteboard: abrt_hash:d3581ec7b8e3f234f554a8b330e0ac037b3f870b
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2015-08-19 20:42:53 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On: 1255169, 1266470    
Bug Blocks:    
Attachments:
Description Flags
File: backtrace
none
File: cgroup
none
File: core_backtrace
none
File: dso_list
none
File: environ
none
File: limits
none
File: machineid
none
File: maps
none
File: open_fds
none
File: proc_pid_status
none
File: var_log_messages none

Description Lubomir Rintel 2015-08-13 13:24:59 UTC
Description of problem:
Beaker run: https://beaker.engineering.redhat.com/jobs/1048794

Aug 13 05:17:39 qe-dell-ovs5-vm-1.dqe.lab.eng.bos.redhat.com nmcli/./runtest.sh[25590]: Running test run_once_new_connection
Aug 13 05:17:40 qe-dell-ovs5-vm-1.dqe.lab.eng.bos.redhat.com systemd[1]: Stopping LSB: Bring up/down networking...
Aug 13 05:17:40 qe-dell-ovs5-vm-1.dqe.lab.eng.bos.redhat.com NetworkManager[25418]: <debug> [1439457460.397707] [nm-bus-manager.c:153] private_server_new_connection(): (private) accepted connection 0x7f88af730e40 on private socket.
Aug 13 05:17:40 qe-dell-ovs5-vm-1.dqe.lab.eng.bos.redhat.com NetworkManager[25418]: <debug> [1439457460.449782] [nm-bus-manager.c:126] private_server_closed(): (private) closed connection 0x7f88af730e40 on private socket.
...
Aug 13 05:18:14 qe-dell-ovs5-vm-1.dqe.lab.eng.bos.redhat.com NetworkManager[26813]: <debug> [1439457494.681665] [nm-bus-manager.c:126] private_server_closed(): (private) closed connection 0x7fb852392c40 on private socket.
Aug 13 05:18:14 qe-dell-ovs5-vm-1.dqe.lab.eng.bos.redhat.com NetworkManager[26813]: <debug> [1439457494.682629] [nm-bus-manager.c:153] private_server_new_connection(): (private) accepted connection 0x7fb852392940 on private socket.
Aug 13 05:18:14 qe-dell-ovs5-vm-1.dqe.lab.eng.bos.redhat.com NetworkManager[26813]: <debug> [1439457494.683193] [nm-sleep-monitor-systemd.c:115] inhibit_done(): Inhibitor fd is 24
Aug 13 05:18:14 qe-dell-ovs5-vm-1.dqe.lab.eng.bos.redhat.com NetworkManager[26813]: <debug> [1439457494.683316] [nm-bus-manager.c:126] private_server_closed(): (private) closed connection 0x7fb852392940 on private socket.
Aug 13 05:18:14 qe-dell-ovs5-vm-1.dqe.lab.eng.bos.redhat.com NetworkManager[26813]: <info>  ModemManager available in the bus
Aug 13 05:18:14 qe-dell-ovs5-vm-1.dqe.lab.eng.bos.redhat.com NetworkManager[26813]: <debug> [1439457494.686330] [nm-bus-manager.c:153] private_server_new_connection(): (private) accepted connection 0x7fb852392d40 on private socket.
Aug 13 05:18:14 qe-dell-ovs5-vm-1.dqe.lab.eng.bos.redhat.com NetworkManager[26813]: <debug> [1439457494.686713] [nm-bus-manager.c:126] private_server_closed(): (private) closed connection 0x7fb852392d40 on private socket.
Aug 13 05:18:14 qe-dell-ovs5-vm-1.dqe.lab.eng.bos.redhat.com NetworkManager[26813]: (NetworkManager:26813): GLib-GIO-WARNING **: Error sending message: The connection is closed
Aug 13 05:18:14 qe-dell-ovs5-vm-1.dqe.lab.eng.bos.redhat.com kernel: traps: NetworkManager[26813] trap int3 ip:7fb84dd5e8c3 sp:7ffe8188b200 error:0
Aug 13 05:18:14 qe-dell-ovs5-vm-1.dqe.lab.eng.bos.redhat.com abrt-hook-ccpp[26847]: Not saving repeating crash in '/usr/sbin/NetworkManager'
Aug 13 05:18:14 qe-dell-ovs5-vm-1.dqe.lab.eng.bos.redhat.com abrt-hook-ccpp[26847]: Saved core dump of pid 26813 to core.26813 at / (54734848 bytes)
Aug 13 05:18:14 qe-dell-ovs5-vm-1.dqe.lab.eng.bos.redhat.com systemd[1]: NetworkManager.service: main process exited, code=dumped, status=5/TRAP

Version-Release number of selected component:
NetworkManager-1.1.0-12796.8810036895.el7.centos

Additional info:
reporter:       libreport-2.1.11
backtrace_rating: 4
cmdline:        /usr/sbin/NetworkManager --no-daemon
crash_function: g_dbus_method_invocation_return_value_internal
executable:     /usr/sbin/NetworkManager
kernel:         3.10.0-302.el7.x86_64
runlevel:       N 3
type:           CCpp
uid:            0

Truncated backtrace:
Thread no. 1 (10 frames)
 #2 g_dbus_method_invocation_return_value_internal at gdbusmethodinvocation.c:508
 #3 g_dbus_method_invocation_return_value at gdbusmethodinvocation.c:535
 #4 get_settings_auth_cb at settings/nm-settings-connection.c:1265
 #5 auth_start at settings/nm-settings-connection.c:1161
 #6 impl_settings_connection_get_settings at settings/nm-settings-connection.c:1280
 #7 ffi_call_unix64 at ../src/x86/unix64.S:76
 #8 ffi_call at ../src/x86/ffi64.c:522
 #9 g_cclosure_marshal_generic at gclosure.c:1448
 #10 nm_exported_object_meta_marshal at nm-exported-object.c:345
 #13 g_signal_emitv at gsignal.c:3048

Comment 1 Lubomir Rintel 2015-08-13 13:25:01 UTC
Created attachment 1062543 [details]
File: backtrace

Comment 2 Lubomir Rintel 2015-08-13 13:25:02 UTC
Created attachment 1062544 [details]
File: cgroup

Comment 3 Lubomir Rintel 2015-08-13 13:25:03 UTC
Created attachment 1062545 [details]
File: core_backtrace

Comment 4 Lubomir Rintel 2015-08-13 13:25:04 UTC
Created attachment 1062546 [details]
File: dso_list

Comment 5 Lubomir Rintel 2015-08-13 13:25:05 UTC
Created attachment 1062547 [details]
File: environ

Comment 6 Lubomir Rintel 2015-08-13 13:25:05 UTC
Created attachment 1062548 [details]
File: limits

Comment 7 Lubomir Rintel 2015-08-13 13:25:06 UTC
Created attachment 1062549 [details]
File: machineid

Comment 8 Lubomir Rintel 2015-08-13 13:25:07 UTC
Created attachment 1062550 [details]
File: maps

Comment 9 Lubomir Rintel 2015-08-13 13:25:08 UTC
Created attachment 1062551 [details]
File: open_fds

Comment 10 Lubomir Rintel 2015-08-13 13:25:09 UTC
Created attachment 1062552 [details]
File: proc_pid_status

Comment 11 Lubomir Rintel 2015-08-13 13:25:10 UTC
Created attachment 1062553 [details]
File: var_log_messages

Comment 15 Thomas Haller 2015-08-13 15:45:48 UTC
I don't see the reason for this warning.

Looking at g_dbus_method_invocation_return_value_internal() in glib/gio/gdbusmethodinvocation.c:

  error = NULL;
  if (!g_dbus_connection_send_message (g_dbus_method_invocation_get_connection (invocation), reply, G_DBUS_SEND_MESSAGE_FLAGS_NONE, NULL, &error))
    { 
      g_warning ("Error sending message: %s", error->message);
      g_error_free (error);
    }



Seems like a glib bug to me.


CC-ing danw

Comment 16 Dan Winship 2015-08-13 17:30:31 UTC
I guess the assumption is that errors shouldn't normally occur there, and if they do, there's not really anything the caller could do about it, so it doesn't make sense to return a GError to the caller, but at the same time, if something does go wrong, we need to let the programmer know somehow...

In this particular case though (G_IO_ERROR_CLOSED), the warning isn't at all useful, and due to the multi-threadedness of gdbus, I don't even think you can completely reliably prevent it by checking g_dbus_connection_is_closed() before g_method_invocation_return_value(). (Though NM could do that anyway to *mostly* get rid of it) So probably glib should skip the warning in this case.

(The warning could be hit from any D-Bus method return that might be on a private connection... which I think means every D-Bus method return in the daemon.)

Comment 17 Dan Winship 2015-08-19 17:56:38 UTC
filed https://bugzilla.gnome.org/show_bug.cgi?id=753839 for the glib issue

Comment 18 Thomas Haller 2015-08-19 20:42:53 UTC
I'm closing this one. It's not really a NM issue.

Once bug 1255169 is fixed, this will be obsolete.