Bug 1429604

Summary: gvfsd-trash aborts with a bad event mask
Product: Red Hat Enterprise Linux 7 Reporter: Joe Wright <jwright>
Component: glib2Assignee: Colin Walters <walters>
Status: CLOSED WONTFIX QA Contact: Desktop QE <desktop-qa-list>
Severity: high Docs Contact:
Priority: unspecified    
Version: 7.3CC: alanm, dforziat, jsantos, kwalker, oholy, walters
Target Milestone: rcKeywords: PrioBumpGSS
Target Release: ---Flags: kwalker: needinfo? (walters)
Hardware: x86_64   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2020-08-27 15:41:48 UTC Type: Bug
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:    
Bug Blocks: 1420851    

Description Joe Wright 2017-03-06 16:46:08 UTC
Description of problem:
- gvfsd-trash aborts with a bad event mask

Version-Release number of selected component (if applicable):
- gvfs-1.22.4-8.el7

How reproducible:
- unsure

Steps to Reproduce:
1. unsure
2.
3.

Actual results:
- signal 6 crash

Expected results:


Additional info:

Core was generated by `/usr/libexec/gvfsd-trash --spawner :1.3 /org/gtk/gvfs/exec_spaw/0'.
Program terminated with signal 6, Aborted.
#0  0x00007f796e4081d7 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56
56	  return INLINE_SYSCALL (tgkill, 3, pid, selftid, sig);
Missing separate debuginfos, use: debuginfo-install systemd-libs-219-30.el7_3.3.x86_64
(gdb) bt
#0  0x00007f796e4081d7 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56
#1  0x00007f796e4098c8 in __GI_abort () at abort.c:90
#2  0x00007f796ec212a5 in g_assertion_message (domain=domain@entry=0x7f796f240358 "GLib-GIO", file=file@entry=0x7f796f26e153 "glocalfilemonitor.c", line=line@entry=433, 
    func=func@entry=0x7f796f26e460 <__FUNCTION__.24145> "g_file_monitor_source_handle_event", message=message@entry=0x7f7960018a00 "code should not be reached") at gtestutils.c:2429
#3  0x00007f796ec2133a in g_assertion_message_expr (domain=domain@entry=0x7f796f240358 "GLib-GIO", file=file@entry=0x7f796f26e153 "glocalfilemonitor.c", line=line@entry=433, 
    func=func@entry=0x7f796f26e460 <__FUNCTION__.24145> "g_file_monitor_source_handle_event", expr=expr@entry=0x0) at gtestutils.c:2444
#4  0x00007f796f235b22 in g_file_monitor_source_handle_event (fms=0x6be3f0, event_type=4294967295, child=0x7f796001ad40 "PESO.CSV", rename_to=rename_to@entry=0x0, other=other@entry=0x0, 
    event_time=449344021705) at glocalfilemonitor.c:433
#5  0x00007f796f23b7dd in ih_event_callback (event=0x7f796001aa60, sub=0x6b0950, file_event=<optimized out>) at inotify-helper.c:201
#6  0x00007f796f23ac28 in ip_event_dispatch (dir_list=dir_list@entry=0x7f7960009380, file_list=0x0, event=event@entry=0x7f796001aa60) at inotify-path.c:493
#7  0x00007f796f23adf6 in ip_event_callback (event=event@entry=0x7f796001aa60) at inotify-path.c:547
#8  0x00007f796f23a1f2 in ik_source_dispatch (source=0x7f7960006ce0, func=0x7f796f23ad30 <ip_event_callback>, user_data=<optimized out>) at inotify-kernel.c:321
#9  0x00007f796ebfcd7a in g_main_dispatch (context=0x680dc0) at gmain.c:3152
#10 g_main_context_dispatch (context=context@entry=0x680dc0) at gmain.c:3767
#11 0x00007f796ebfd0b8 in g_main_context_iterate (context=context@entry=0x680dc0, block=block@entry=1, dispatch=dispatch@entry=1, self=<optimized out>) at gmain.c:3838
#12 0x00007f796ebfd16c in g_main_context_iteration (context=0x680dc0, may_block=may_block@entry=1) at gmain.c:3899
#13 0x00007f796ebfd1a9 in glib_worker_main (data=<optimized out>) at gmain.c:5670
#14 0x00007f796ec220f5 in g_thread_proxy (data=0x683050) at gthread.c:778
#15 0x00007f796e79bdc5 in start_thread (arg=0x7f79664cd700) at pthread_create.c:308
#16 0x00007f796e4ca73d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113
(gdb) f 2
#2  0x00007f796ec212a5 in g_assertion_message (domain=domain@entry=0x7f796f240358 "GLib-GIO", file=file@entry=0x7f796f26e153 "glocalfilemonitor.c", line=line@entry=433, 
    func=func@entry=0x7f796f26e460 <__FUNCTION__.24145> "g_file_monitor_source_handle_event", message=message@entry=0x7f7960018a00 "code should not be reached") at gtestutils.c:2429
2429	    abort ();
(gdb) list
2424	       * to avoid triggering any system crash-reporting daemon.
2425	       */
2426	      _exit (1);
2427	    }
2428	  else
2429	    abort ();
2430	}
2431	
2432	void
2433	g_assertion_message_expr (const char     *domain,
(gdb) f 3
#3  0x00007f796ec2133a in g_assertion_message_expr (domain=domain@entry=0x7f796f240358 "GLib-GIO", file=file@entry=0x7f796f26e153 "glocalfilemonitor.c", line=line@entry=433, 
    func=func@entry=0x7f796f26e460 <__FUNCTION__.24145> "g_file_monitor_source_handle_event", expr=expr@entry=0x0) at gtestutils.c:2444
2444	  g_assertion_message (domain, file, line, func, s);
(gdb) list
2439	  char *s;
2440	  if (!expr)
2441	    s = g_strdup ("code should not be reached");
2442	  else
2443	    s = g_strconcat ("assertion failed: (", expr, ")", NULL);
2444	  g_assertion_message (domain, file, line, func, s);
2445	  g_free (s);
2446	
2447	  /* Normally g_assertion_message() won't return, but we need this for
2448	   * when test_nonfatal_assertions is set, since
(gdb) f 4
#4  0x00007f796f235b22 in g_file_monitor_source_handle_event (fms=0x6be3f0, event_type=4294967295, child=0x7f796001ad40 "PESO.CSV", rename_to=rename_to@entry=0x0, other=other@entry=0x0, 
    event_time=449344021705) at glocalfilemonitor.c:433
433	      g_assert_not_reached ();
(gdb) list
428	      break;
429	
430	    case G_FILE_MONITOR_EVENT_MOVED:
431	      /* was never available in this API */
432	    default:
433	      g_assert_not_reached ();
434	    }
435	
436	  g_file_monitor_source_update_ready_time (fms);
437	
(gdb) f 5
#5  0x00007f796f23b7dd in ih_event_callback (event=0x7f796001aa60, sub=0x6b0950, file_event=<optimized out>) at inotify-helper.c:201
201	    interesting = g_file_monitor_source_handle_event (sub->user_data, ih_mask_to_EventFlags (event->mask),
(gdb) list
196	            g_object_unref (other);
197	        }
198	    }
199	  else
200	    /* unpaired event -- no 'other' field */
201	    interesting = g_file_monitor_source_handle_event (sub->user_data, ih_mask_to_EventFlags (event->mask),
202	                                                      event->name, NULL, NULL, event->timestamp);
203	
204	  if (event->mask & IN_CREATE)
205	    {
(gdb) f 6
#6  0x00007f796f23ac28 in ip_event_dispatch (dir_list=dir_list@entry=0x7f7960009380, file_list=0x0, event=event@entry=0x7f796001aa60) at inotify-path.c:493
493		  interesting |= event_callback (event, sub, FALSE);
(gdb) list
488		  /* FIXME: We might need to synthesize
489		   * DELETE/UNMOUNT events when
490		   * the filename doesn't match
491		   */
492		  
493		  interesting |= event_callback (event, sub, FALSE);
494	
495	          if (sub->hardlinks)
496	            {
497	              ip_watched_file_t *file;
(gdb) f 7 
#7  0x00007f796f23adf6 in ip_event_callback (event=event@entry=0x7f796001aa60) at inotify-path.c:547
547	    interesting |= ip_event_dispatch (dir_list, file_list, event);
(gdb) list
542	
543	  dir_list = g_hash_table_lookup (wd_dir_hash, GINT_TO_POINTER (event->wd));
544	  file_list = g_hash_table_lookup (wd_file_hash, GINT_TO_POINTER (event->wd));
545	
546	  if (event->mask & IP_INOTIFY_DIR_MASK)
547	    interesting |= ip_event_dispatch (dir_list, file_list, event);
548	
549	  /* Only deliver paired events if the wds are separate */
550	  if (event->pair && event->pair->wd != event->wd)
551	    {
(gdb) f 8
#8  0x00007f796f23a1f2 in ik_source_dispatch (source=0x7f7960006ce0, func=0x7f796f23ad30 <ip_event_callback>, user_data=<optimized out>) at inotify-kernel.c:321
321	      interesting |= (* user_callback) (event);
(gdb) list
316	      if (event->mask & IN_MOVED_FROM && !event->pair)
317	        g_hash_table_remove (iks->unmatched_moves, GUINT_TO_POINTER (event->cookie));
318	
319	      G_LOCK (inotify_lock);
320	
321	      interesting |= (* user_callback) (event);
322	
323	      G_UNLOCK (inotify_lock);
324	    }
325
(gdb) f 9
#9  0x00007f796ebfcd7a in g_main_dispatch (context=0x680dc0) at gmain.c:3152
3152	          need_destroy = !(* dispatch) (source, callback, user_data);
(gdb) list
3147	          prev_source = current->source;
3148	          current->source = source;
3149	          current->depth++;
3150	
3151		  TRACE( GLIB_MAIN_BEFORE_DISPATCH (g_source_get_name (source)));
3152	          need_destroy = !(* dispatch) (source, callback, user_data);
3153		  TRACE( GLIB_MAIN_AFTER_DISPATCH (g_source_get_name (source)));
3154	
3155	          current->source = prev_source;
3156	          current->depth--;
(gdb) f 10
#10 g_main_context_dispatch (context=context@entry=0x680dc0) at gmain.c:3767
3767	      g_main_dispatch (context);
(gdb) list
3762	{
3763	  LOCK_CONTEXT (context);
3764	
3765	  if (context->pending_dispatches->len > 0)
3766	    {
3767	      g_main_dispatch (context);
3768	    }
3769	
3770	  UNLOCK_CONTEXT (context);
3771	}


from frame 4:

(gdb) info locals
interesting = 1
__FUNCTION__ = "g_file_monitor_source_handle_event"
(gdb) info args
fms = 0x6be3f0
event_type = 4294967295
child = 0x7f796001ad40 "PESO.CSV"
rename_to = 0x0
other = 0x0
event_time = 449344021705
(gdb) info frame
Stack level 4, frame at 0x7f79664cbb40:
 rip = 0x7f796f235b22 in g_file_monitor_source_handle_event (glocalfilemonitor.c:433); saved rip 0x7f796f23b7dd
 called by frame at 0x7f79664cbc10, caller of frame at 0x7f79664cbaf0
 source language c.
 Arglist at 0x7f79664cbae8, args: fms=0x6be3f0, event_type=4294967295, child=0x7f796001ad40 "PESO.CSV", rename_to=rename_to@entry=0x0, other=other@entry=0x0, event_time=449344021705
 Locals at 0x7f79664cbae8, Previous frame's sp is 0x7f79664cbb40
 Saved registers:
  rbx at 0x7f79664cbb08, rbp at 0x7f79664cbb10, r12 at 0x7f79664cbb18, r13 at 0x7f79664cbb20, r14 at 0x7f79664cbb28, r15 at 0x7f79664cbb30, rip at 0x7f79664cbb38i
(gdb) info all-registers
rax            0x0	0
rbx            0x7f796001ad40	140159278492992
rcx            0xffffffffffffffff	-1
rdx            0x6	6
rsi            0x3d00	15616
rdi            0x3cff	15615
rbp            0x6be3f0	0x6be3f0
rsp            0x7f79664cbaf0	0x7f79664cbaf0
r8             0x80000000	2147483648
r9             0x7f7960018ba0	140159278484384
r10            0x8	8
r11            0x206	518
r12            0x0	0
r13            0xffffffff	4294967295 <--------------------------------------------------
r14            0x6be450	7070800
r15            0x0	0
rip            0x7f796f235b22	0x7f796f235b22 <g_file_monitor_source_handle_event+898>
eflags         0x206	[ PF IF ]
cs             0x33	51
ss             0x2b	43
ds             0x0	0
es             0x0	0
fs             0x0	0
gs             0x0	0
st0            *value not available*
st1            *value not available*
st2            *value not available*
st3            *value not available*
st4            *value not available*
st5            *value not available*
st6            *value not available*
st7            *value not available*
fctrl          *value not available*
fstat          *value not available*
ftag           *value not available*
fiseg          *value not available*
fioff          *value not available*




(gdb) f 5
#5  0x00007f796f23b7dd in ih_event_callback (event=0x7f796001aa60, sub=0x6b0950, file_event=<optimized out>) at inotify-helper.c:201
201	    interesting = g_file_monitor_source_handle_event (sub->user_data, ih_mask_to_EventFlags (event->mask),
(gdb) print event->mask
$1 = 6
(gdb) list ih_mask_to_EventFlags
249	
250	/* Transforms a inotify event to a GVFS event. */
251	static GFileMonitorEvent
252	ih_mask_to_EventFlags (guint32 mask)
253	{
254	  mask &= ~IN_ISDIR;
255	  switch (mask)
256	    {
257	    case IN_MODIFY:
258	      return G_FILE_MONITOR_EVENT_CHANGED;
(gdb) 
259	    case IN_CLOSE_WRITE:
260	      return G_FILE_MONITOR_EVENT_CHANGES_DONE_HINT;
261	    case IN_ATTRIB:
262	      return G_FILE_MONITOR_EVENT_ATTRIBUTE_CHANGED;
263	    case IN_MOVE_SELF:
264	    case IN_DELETE:
265	    case IN_DELETE_SELF:
266	      return G_FILE_MONITOR_EVENT_DELETED;
267	    case IN_CREATE:
268	      return G_FILE_MONITOR_EVENT_CREATED;
(gdb) 
269	    case IN_MOVED_FROM:
270	      return G_FILE_MONITOR_EVENT_MOVED_OUT;
271	    case IN_MOVED_TO:
272	      return G_FILE_MONITOR_EVENT_MOVED_IN;
273	    case IN_UNMOUNT:
274	      return G_FILE_MONITOR_EVENT_UNMOUNTED;
275	    case IN_Q_OVERFLOW:
276	    case IN_OPEN:
277	    case IN_CLOSE_NOWRITE:
278	    case IN_ACCESS:
(gdb) 
279	    case IN_IGNORED:
280	    default:
281	      return -1;
282	    }
283	}


Did we go all the way to a -1?
http://softwareengineering.stackexchange.com/questions/239036/how-are-negative-signed-values-stored

(gdb) print IN_ISDIR
No symbol "IN_ISDIR" in current context.  <------- what is this?



back to f 4



(gdb) f 4
#4  0x00007f796f235b22 in g_file_monitor_source_handle_event (fms=0x6be3f0, event_type=4294967295, child=0x7f796001ad40 "PESO.CSV", rename_to=rename_to@entry=0x0, other=other@entry=0x0, 
    event_time=449344021705) at llist
433	      g_assert_not_reached ();
(gdb) list g_file_monitor_source_handle_event
336	                                    GFileMonitorEvent   event_type,
337	                                    const gchar        *child,
338	                                    const gchar        *rename_to,
339	                                    GFile              *other,
340	                                    gint64              event_time)
341	{
342	  gboolean interesting = TRUE;
343	
344	  g_assert (!child || is_basename (child));
345	  g_assert (!rename_to || is_basename (rename_to));



(gdb) list 332
327	{
328	  if (name[0] == '.' && ((name[1] == '.' && name[2] == '\0') || name[1] == '\0'))
329	    return FALSE;
330	
331	  return !strchr (name, '/');
332	}
333	
334	gboolean
335	g_file_monitor_source_handle_event (GFileMonitorSource *fms,
336	                                    GFileMonitorEvent   event_type, <----------------------
(gdb) 
337	                                    const gchar        *child,
338	                                    const gchar        *rename_to,
339	                                    GFile              *other,
340	                                    gint64              event_time)


(gdb) list ../../gio/gioenums.h:415
410	 * @G_FILE_MONITOR_EVENT_MOVED_OUT: the file was moved out of the
411	 *   monitored directory to another location -- only sent if the
412	 *   %G_FILE_MONITOR_WATCH_MOVES flag is set.  Since: 2.44
413	 *
414	 * Specifies what type of event a monitor event is.
415	 **/
416	typedef enum {
417	  G_FILE_MONITOR_EVENT_CHANGED,
418	  G_FILE_MONITOR_EVENT_CHANGES_DONE_HINT,
419	  G_FILE_MONITOR_EVENT_DELETED,
(gdb) 
420	  G_FILE_MONITOR_EVENT_CREATED,
421	  G_FILE_MONITOR_EVENT_ATTRIBUTE_CHANGED,
422	  G_FILE_MONITOR_EVENT_PRE_UNMOUNT,
423	  G_FILE_MONITOR_EVENT_UNMOUNTED,
424	  G_FILE_MONITOR_EVENT_MOVED,
425	  G_FILE_MONITOR_EVENT_RENAMED,
426	  G_FILE_MONITOR_EVENT_MOVED_IN,
427	  G_FILE_MONITOR_EVENT_MOVED_OUT
428	} GFileMonitorEvent;
429	




either "6" was bad when we passed it in to ih_mask_to_EventFlags, or the transformation function somehow returned a '-1' and there was oversight for graceful handling before passing as an arg to g_file_monitor_source_handle_event?

(gdb) f 5
#5  0x00007f796f23b7dd in ih_event_callback (event=0x7f796001aa60, sub=0x6b0950, file_event=<optimized out>) at inotify-helper.c:201
201	    interesting = g_file_monitor_source_handle_event (sub->user_data, ih_mask_to_EventFlags (event->mask),

That or theres some form of memory corruption here... unsure specifically

Comment 3 Ondrej Holy 2017-03-07 10:16:49 UTC
I don't think we can do much with it in GVfs. gvfsd-trash just calls g_file_monitor_directory without any flags... and it obviously affects more component as per FAF:
https://retrace.fedoraproject.org/faf/problems/?function_names=g_file_monitor_source_handle_event

It seems to me that ih_mask_to_EventFlags returns -1 for valid inotify events (i.e. IN_Q_OVERFLOW, IN_OPEN, IN_CLOSE_NOWRITE, IN_ACCESS, IN_IGNORED), but the following code doesn't expect such value and aborted. So the code should check the returned value and stop processing for -1.

It might be introduced by the following patch, which is the latest bigger change:
https://git.gnome.org/browse/glib/commit/?id=2737ab3201163631be152801a859b3874a667f10

Are you able to reproduce it somehow?

Comment 4 Joe Wright 2017-03-21 15:08:48 UTC
I personally haven't.

Comment 5 Diego 2017-05-15 12:12:55 UTC
Hi Team:

Do we have any update on this bug?

thanks!

Regards

Comment 6 Diego 2018-02-16 15:07:59 UTC
Hi Team:

Do we have any update on this bug?

thanks!

Regards

Comment 7 Diego 2018-04-16 11:30:33 UTC
Team:

This bug was opened one year ago and is in NEW state. Please, let me know if you need anything to reproduce it and help the customer.

Regards

Comment 11 Tomas Popela 2020-08-27 14:42:34 UTC
Closing the bug as the attached customer case is closed.