Re: [gamin] Re: Building gamin 0.1.6

[John McCutchan <ttb tentacle dhs org>]

On Sun, 2005-23-10 at 12:44 +1300, Mark Carey wrote:
> Ok so I have rebuilt gamin with debug support and poll, dnotify and inotify
> backends.
> 
> Following the instructions at http://www.gnome.org/~veillard/gamin/debug.html my
> system does not have a gamin_client program so I am not quite sure what to do,
> but I tried the following.
> 
> Terminal 1 started,
> 
> $ export GAM_DEBUG=
> $ /opt/gnome2.12.1/libexec/gam_server --notimeout test \
>   > gamin-server-output.log 2>&1
> *** glibc detected *** double free or corruption (fasttop): 0x0807c778 ***
> Aborted
> 
> Note here that the message from glibc is not immediate it only ocurrs after we
> manage to capture the contents listed below.
> (http://homepages.paradise.net.nz/markcare/linux/gamin/1/gamin-server-output.log)
> 
> In Terminal 2,
> 
> $ export GAM_DEBUG=
> $ export GAM_CLIENT_ID=test
> $ startx > x-gam-debug.log 2>&1
> 
> Atttached complete contents of gamin-server-output.log
> (http://homepages.paradise.net.nz/markcare/linux/gamin/1/gamin-server-output.log)
> 
> added /media/*,1 to excludes
> added /mnt/*,1 to excludes
> added /dev/*,1 to excludes
> added /proc/*,1 to excludes
> Updating list of mounted filesystems
> g_n_n: node for / using kernel with poll timeout of 0
> basic poll backend initialized
> inotify backend initialized
> Using inotify as backend
> Ready listening to socket /tmp/fam-mark-test : 4
> gam_incoming_conn_read called
> accepted incoming connection: 5
> Created connection 5
> gam_client_conn_read called
> read credentials byte
> Credentials: s_uid 511, c_uid 511, c_gid 511, c_pid 4692
> gam_client_conn_read called
> MONFILE request: from /opt/gnome2.12.1/libexec/gnome-settings-daemon,
> seq 1, type 1 options 0
> /opt/gnome2.12.1/libexec/gnome-settings-daemon listening for
> /home/mark/.local/share/applications/mimeinfo.cache
> g_a_s: /home/mark/.local/share/applications/mimeinfo.cache using poll monitoring
> Adding sub /home/mark/.local/share/applications/mimeinfo.cache to
> listener /opt/gnome2.12.1/libexec/gnome-settings-daemon
> g_n_n: node for /home using poll with poll timeout of 5
> g_n_n: node for /home/mark using poll with poll timeout of 5
> g_n_n: node for /home/mark/.local using poll with poll timeout of 5
> g_n_n: node for /home/mark/.local/share using poll with poll timeout of 5
> g_n_n: node for /home/mark/.local/share/applications using poll with
> poll timeout of 5


Inotify isn't being used for your home directory. What FS type is it?

> g_n_n: node for /home/mark/.local/share/applications/mimeinfo.cache
> using poll with poll timeout of 5
> poll-basic: 0 && 1130011586 < 5
> Poll: poll_file for /home/mark/.local/share/applications/mimeinfo.cache called
> Poll: file is new
> New file subscription:
> /home/mark/.local/share/applications/mimeinfo.cache event 0
> Poll: Adding node /home/mark/.local/share/applications/mimeinfo.cache
> Poll: added subscription for /home/mark/.local/share/applications/mimeinfo.cache
> gam_client_conn_read called
> MONFILE request: from /opt/gnome2.12.1/libexec/gnome-settings-daemon,
> seq 2, type 1 options 0
> /opt/gnome2.12.1/libexec/gnome-settings-daemon listening for
> /home/mark/.local/share/applications/defaults.list
> g_a_s: /home/mark/.local/share/applications/defaults.list using poll monitoring
> Adding sub /home/mark/.local/share/applications/defaults.list to
> listener /opt/gnome2.12.1/libexec/gnome-settings-daemon
> g_n_n: node for /home/mark/.local/share/applications/defaults.list
> using poll with poll timeout of 5
> poll-basic: 0 && 1130011586 < 5
> Poll: poll_file for /home/mark/.local/share/applications/defaults.list called
> Poll: file is new
> New file subscription:
> /home/mark/.local/share/applications/defaults.list event 0
> Poll: Adding node /home/mark/.local/share/applications/defaults.list
> Poll: added subscription for /home/mark/.local/share/applications/defaults.list
> gam_client_conn_read called
> MONFILE request: from /opt/gnome2.12.1/libexec/gnome-settings-daemon,
> seq 3, type 1 options 0
> /opt/gnome2.12.1/libexec/gnome-settings-daemon listening for
> /opt/gnome2.12.1/share/applications/mimeinfo.cache
> g_a_s: /opt/gnome2.12.1/share/applications/mimeinfo.cache using kernel
> monitoring
> inotify: success adding watch for
> /opt/gnome2.12.1/share/applications/mimeinfo.cache (wd = 1)
> Adding sub /opt/gnome2.12.1/share/applications/mimeinfo.cache to
> listener /opt/gnome2.12.1/libexec/gnome-settings-daemon
> inotify: Sending initial events for
> /opt/gnome2.12.1/share/applications/mimeinfo.cache
> gam_client_conn_read called
> MONFILE request: from /opt/gnome2.12.1/libexec/gnome-settings-daemon,
> seq 4, type 1 options 0
> /opt/gnome2.12.1/libexec/gnome-settings-daemon listening for
> /opt/gnome2.12.1/share/applications/defaults.list
> g_a_s: /opt/gnome2.12.1/share/applications/defaults.list using kernel monitoring
> inotify: failed to add watch for
> /opt/gnome2.12.1/share/applications/defaults.list
> inotify: reason 2 = No such file or directory
> inotify: could not add watch for
> /opt/gnome2.12.1/share/applications/defaults.list
> inotify: adding /opt/gnome2.12.1/share/applications/defaults.list to
> missing list MISSING
> inotify-missing: add - /opt/gnome2.12.1/share/applications/defaults.list
> Adding sub /opt/gnome2.12.1/share/applications/defaults.list to
> listener /opt/gnome2.12.1/libexec/gnome-settings-daemon
> inotify: Sending initial events for
> /opt/gnome2.12.1/share/applications/defaults.list -- WAS_MISSING
> Event to /opt/gnome2.12.1/libexec/gnome-settings-daemon : 1, 8,
> /home/mark/.local/share/applications/mimeinfo.cache Exists
> Event to /opt/gnome2.12.1/libexec/gnome-settings-daemon : 1, 9,
> /home/mark/.local/share/applications/mimeinfo.cache None
> Event to /opt/gnome2.12.1/libexec/gnome-settings-daemon : 2, 8,
> /home/mark/.local/share/applications/defaults.list Exists
> Event to /opt/gnome2.12.1/libexec/gnome-settings-daemon : 2, 9,
> /home/mark/.local/share/applications/defaults.list None
> Event to /opt/gnome2.12.1/libexec/gnome-settings-daemon : 3, 8,
> /opt/gnome2.12.1/share/applications/mimeinfo.cache Exists
> Event to /opt/gnome2.12.1/libexec/gnome-settings-daemon : 3, 9,
> /opt/gnome2.12.1/share/applications/mimeinfo.cache None
> Event to /opt/gnome2.12.1/libexec/gnome-settings-daemon : 4, 2,
> /opt/gnome2.12.1/share/applications/defaults.list Deleted
> Event to /opt/gnome2.12.1/libexec/gnome-settings-daemon : 4, 9,
> /opt/gnome2.12.1/share/applications/defaults.list None
> poll-basic: not enough time passed for
> /home/mark/.local/share/applications/defaults.list
> poll-basic: not enough time passed for
> /home/mark/.local/share/applications/mimeinfo.cache
> poll-basic: not enough time passed for
> /home/mark/.local/share/applications/defaults.list
> poll-basic: not enough time passed for
> /home/mark/.local/share/applications/mimeinfo.cache
> gam_incoming_conn_read called
> accepted incoming connection: 6
> Created connection 6
> gam_client_conn_read called
> read credentials byte
> Credentials: s_uid 511, c_uid 511, c_gid 511, c_pid 4717
> gam_client_conn_read called
> MONFILE request: from nautilus, seq 1, type 1 options 0
> nautilus listening for /home/mark/.local/share/applications/mimeinfo.cache
> g_a_s: /home/mark/.local/share/applications/mimeinfo.cache using poll monitoring
> Adding sub /home/mark/.local/share/applications/mimeinfo.cache to
> listener nautilus
> poll-basic: not enough time passed for
> /home/mark/.local/share/applications/mimeinfo.cache
> New file subscription:
> /home/mark/.local/share/applications/mimeinfo.cache event 0
> Poll: added subscription for /home/mark/.local/share/applications/mimeinfo.cache
> gam_client_conn_read called
> MONFILE request: from nautilus, seq 2, type 1 options 0
> nautilus listening for /home/mark/.local/share/applications/defaults.list
> g_a_s: /home/mark/.local/share/applications/defaults.list using poll monitoring
> Adding sub /home/mark/.local/share/applications/defaults.list to
> listener nautilus
> poll-basic: not enough time passed for
> /home/mark/.local/share/applications/defaults.list
> New file subscription:
> /home/mark/.local/share/applications/defaults.list event 0
> Poll: added subscription for /home/mark/.local/share/applications/defaults.list
> gam_client_conn_read called
> MONFILE request: from nautilus, seq 3, type 1 options 0
> nautilus listening for /opt/gnome2.12.1/share/applications/mimeinfo.cache
> g_a_s: /opt/gnome2.12.1/share/applications/mimeinfo.cache using kernel
> monitoring
> inotify: Sending initial events for
> /opt/gnome2.12.1/share/applications/mimeinfo.cache
> Adding sub /opt/gnome2.12.1/share/applications/mimeinfo.cache to
> listener nautilus
> gam_client_conn_read called
> MONFILE request: from nautilus, seq 4, type 1 options 0
> nautilus listening for /opt/gnome2.12.1/share/applications/defaults.list
> g_a_s: /opt/gnome2.12.1/share/applications/defaults.list using kernel monitoring
> inotify: Sending initial events for
> /opt/gnome2.12.1/share/applications/defaults.list -- WAS_MISSING
> Adding sub /opt/gnome2.12.1/share/applications/defaults.list to
> listener nautilus
> Event to nautilus : 1, 8,
> /home/mark/.local/share/applications/mimeinfo.cache Exists
> Event to nautilus : 1, 9,
> /home/mark/.local/share/applications/mimeinfo.cache None
> Event to nautilus : 2, 8,
> /home/mark/.local/share/applications/defaults.list Exists
> Event to nautilus : 2, 9,
> /home/mark/.local/share/applications/defaults.list None
> Event to nautilus : 3, 8,
> /opt/gnome2.12.1/share/applications/mimeinfo.cache Exists
> Event to nautilus : 3, 9,
> /opt/gnome2.12.1/share/applications/mimeinfo.cache None
> Event to nautilus : 4, 2,
> /opt/gnome2.12.1/share/applications/defaults.list Deleted
> Event to nautilus : 4, 9, /opt/gnome2.12.1/share/applications/defaults.list None
> gam_incoming_conn_read called
> accepted incoming connection: 7
> Created connection 7
> gam_client_conn_read called
> read credentials byte
> Credentials: s_uid 511, c_uid 511, c_gid 511, c_pid 4724
> gam_client_conn_read called
> MONFILE request: from /opt/gnome2.12.1/libexec/gnome-vfs-daemon, seq
> 1, type 1 options 0
> /opt/gnome2.12.1/libexec/gnome-vfs-daemon listening for /etc/fstab
> g_a_s: /etc/fstab using kernel monitoring
> inotify: success adding watch for /etc/fstab (wd = 2)
> Adding sub /etc/fstab to listener /opt/gnome2.12.1/libexec/gnome-vfs-daemon
> inotify: Sending initial events for /etc/fstab
> gam_client_conn_read called
> MONFILE request: from /opt/gnome2.12.1/libexec/gnome-vfs-daemon, seq
> 2, type 1 options 0
> /opt/gnome2.12.1/libexec/gnome-vfs-daemon listening for /etc/mtab
> g_a_s: /etc/mtab using kernel monitoring
> inotify: success adding watch for /etc/mtab (wd = 3)
> Adding sub /etc/mtab to listener /opt/gnome2.12.1/libexec/gnome-vfs-daemon
> inotify: Sending initial events for /etc/mtab
> Event to /opt/gnome2.12.1/libexec/gnome-vfs-daemon : 1, 8, /etc/fstab Exists
> Event to /opt/gnome2.12.1/libexec/gnome-vfs-daemon : 1, 9, /etc/fstab None
> Event to /opt/gnome2.12.1/libexec/gnome-vfs-daemon : 2, 8, /etc/mtab Exists
> Event to /opt/gnome2.12.1/libexec/gnome-vfs-daemon : 2, 9, /etc/mtab None
> gam_incoming_conn_read called
> accepted incoming connection: 8
> Created connection 8
> gam_client_conn_read called
> read credentials byte
> Credentials: s_uid 511, c_uid 511, c_gid 511, c_pid 4715
> gam_client_conn_read called
> MONFILE request: from gnome-panel, seq 1, type 1 options 0
> gnome-panel listening for /home/mark/.gtk-bookmarks
> g_a_s: /home/mark/.gtk-bookmarks using poll monitoring
> Adding sub /home/mark/.gtk-bookmarks to listener gnome-panel
> g_n_n: node for /home/mark/.gtk-bookmarks using poll with poll timeout of 5
> poll-basic: 0 && 1130011588 < 5
> Poll: poll_file for /home/mark/.gtk-bookmarks called
> Poll: file is new
> New file subscription: /home/mark/.gtk-bookmarks event 0
> Poll: Adding node /home/mark/.gtk-bookmarks
> Poll: added subscription for /home/mark/.gtk-bookmarks
> Event to gnome-panel : 1, 8, /home/mark/.gtk-bookmarks Exists
> Event to gnome-panel : 1, 9, /home/mark/.gtk-bookmarks None
> gam_client_conn_read called
> MONFILE request: from gnome-panel, seq 2, type 1 options 0
> gnome-panel listening for /home/mark/.recently-used
> g_a_s: /home/mark/.recently-used using poll monitoring
> Adding sub /home/mark/.recently-used to listener gnome-panel
> g_n_n: node for /home/mark/.recently-used using poll with poll timeout of 5
> poll-basic: 0 && 1130011589 < 5
> Poll: poll_file for /home/mark/.recently-used called
> Poll: file is new
> New file subscription: /home/mark/.recently-used event 0
> Poll: Adding node /home/mark/.recently-used
> Poll: added subscription for /home/mark/.recently-used
> Event to gnome-panel : 2, 8, /home/mark/.recently-used Exists
> Event to gnome-panel : 2, 9, /home/mark/.recently-used None
> poll-basic: not enough time passed for /home/mark/.recently-used
> poll-basic: not enough time passed for /home/mark/.gtk-bookmarks
> poll-basic: not enough time passed for
> /home/mark/.local/share/applications/defaults.list
> poll-basic: not enough time passed for
> /home/mark/.local/share/applications/mimeinfo.cache
> gam_client_conn_read called
> MONFILE request: from nautilus, seq 5, type 1 options 0
> nautilus listening for /home/mark/.gtk-bookmarks
> g_a_s: /home/mark/.gtk-bookmarks using poll monitoring
> Adding sub /home/mark/.gtk-bookmarks to listener nautilus
> poll-basic: not enough time passed for /home/mark/.gtk-bookmarks
> New file subscription: /home/mark/.gtk-bookmarks event 0
> Poll: added subscription for /home/mark/.gtk-bookmarks
> Event to nautilus : 5, 8, /home/mark/.gtk-bookmarks Exists
> Event to nautilus : 5, 9, /home/mark/.gtk-bookmarks None
> gam_client_conn_read called
> MONDIR request: from nautilus, seq 6, type 2 options 0
> nautilus listening for /home/mark/Desktop
> g_a_s: /home/mark/Desktop using poll monitoring
> Adding sub /home/mark/Desktop to listener nautilus
> g_n_n: node for /home/mark/Desktop using poll with poll timeout of 5
> Looking for existing files in: /home/mark/Desktop
> poll-basic: 0 && 1130011589 < 5
> Poll: poll_file for /home/mark/Desktop called
> Poll: file is new
> Unregistered node /home/mark/Desktop/Internet.desktop
> g_n_n: node for /home/mark/Desktop/Internet.desktop using poll with
> poll timeout of 5
> Unregistered node /home/mark/Desktop/foo
> g_n_n: node for /home/mark/Desktop/foo using poll with poll timeout of 5
> Unregistered node /home/mark/Desktop/Downloads
> g_n_n: node for /home/mark/Desktop/Downloads using poll with poll timeout of 5
> Unregistered node /home/mark/Desktop/LFS-BOOK-SVN-20051005-HTML
> g_n_n: node for /home/mark/Desktop/LFS-BOOK-SVN-20051005-HTML using
> poll with poll timeout of 5
> Unregistered node /home/mark/Desktop/index.html~
> g_n_n: node for /home/mark/Desktop/index.html~ using poll with poll timeout of 5
> Unregistered node /home/mark/Desktop/tms-manual.pdf
> g_n_n: node for /home/mark/Desktop/tms-manual.pdf using poll with poll
> timeout of 5
> Unregistered node /home/mark/Desktop/paradise.css~
> g_n_n: node for /home/mark/Desktop/paradise.css~ using poll with poll
> timeout of 5
> Unregistered node /home/mark/Desktop/foo.d
> g_n_n: node for /home/mark/Desktop/foo.d using poll with poll timeout of 5
> Done scanning /home/mark/Desktop
> Poll: Adding node /home/mark/Desktop
> Poll: added subscription for /home/mark/Desktop
> gam_client_conn_read called
> CANCEL request: from nautilus, seq 6, type 3 options 0
> Cancelling subscription with reqno 6
> Removing sub /home/mark/Desktop from listener nautilus
> nautilus not listening for /home/mark/Desktop
> Tree has 18 nodes
> Removing node /home/mark/Desktop
> remove_directory_subscription /home/mark/Desktop
>   => remove_dir /home/mark/Desktop
> Tree has 9 nodes
> Poll: removed subscription for /home/mark/Desktop
> 

The above looks like a good run of gam_server.

> Attached partial contents of x-gam-debug.log (complete file
> http://homepages.paradise.net.nz/markcare/linux/gamin/1/x-gam-debug.log)
> 
> X Window System Version 6.8.2
> Release Date: 9 February 2005
> X Protocol Version 11, Revision 0, Release 6.8.2
> Build Operating System: Linux 2.6.11.4 i686 [ELF]
> Current Operating System: Linux jersey 2.6.13.4 #1 Sat Oct 22 19:27:50
> NZDT 2005 i686
> Build Date: 07 April 2005
>         Before reporting problems, check http://wiki.X.Org
>         to make sure that you have the latest version.
> Module Loader present
> Markers: (--) probed, (**) from config file, (==) default setting,
>         (++) from command line, (!!) notice, (II) informational,
>         (WW) warning, (EE) error, (NI) not implemented, (??) unknown.
> (==) Log file: "/var/log/Xorg.0.log", Time: Sun Oct 23 09:06:23 2005
> (==) Using config file: "/etc/X11/xorg.conf"
> Could not init font path element /usr/local/X11R6/lib/X11/fonts/CID/,
> removing from list!
> SESSION_MANAGER=local/jersey:/tmp/.ICE-unix/4677
> FAMOpen2()
> FAMOpen()
> Connected to socket /tmp/fam-mark-test : 14
> Wrote credential bytes to socket 14
> Activating thread safety
> FAMPending(fd = 14)
> Checking data available on 14
> Client need auth 14
> read credentials byte
> Credentials: s_uid 511, c_uid 511, c_gid 511, c_pid 4633
> Checking data available on 14
> FAMMonitorFile(/home/mark/.local/share/applications/mimeinfo.cache)
> Wrote 61 bytes to socket 14
> gamin_send_request 1 for socket 14
> Checking data available on 14
> FAMMonitorFile(/home/mark/.local/share/applications/defaults.list)
> Wrote 60 bytes to socket 14
> gamin_send_request 2 for socket 14
> FAMPending(fd = 14)
> Checking data available on 14
> FAMMonitorFile(/opt/gnome2.12.1/share/applications/mimeinfo.cache)
> Wrote 60 bytes to socket 14
> gamin_send_request 3 for socket 14
> FAMPending(fd = 14)
> Checking data available on 14
> FAMMonitorFile(/opt/gnome2.12.1/share/applications/defaults.list)
> Wrote 59 bytes to socket 14
> gamin_send_request 4 for socket 14
> FAMOpen2()
> FAMOpen()
> Connected to socket /tmp/fam-mark-test : 20
> Wrote credential bytes to socket 20
> Activating thread safety
> FAMPending(fd = 20)
> Checking data available on 20
> FAMMonitorFile(/home/mark/.gtk-bookmarks)
> Wrote 35 bytes to socket 20
> gamin_send_request 1 for socket 20
> 
> Note also that when I start gnome without GAM_DEBUG set I get the following
> messages (http://homepages.paradise.net.nz/markcare/linux/gamin/1/x-gam-no-debug.log)
> 

So when you are running gamin with debug option on, you don't get this
error?

> Failed to process 75 bytes from server
> invalid length 10794
> invalid length 10794 invalid length 10794
> invalid length 10794
> invalid length 10794
> invalid length 10794
> invalid length 10794
> Failed to process 89 bytes from server invalid length 10794
> invalid length 10794
> invalid length 10794
> invalid length 10794 invalid length 10794 invalid length 10794
> end from FAM server connection
> invalid length 10794 invalid length 10794
> invalid length 10794
> invalid length 10794
> invalid length 10794
> 
> As indicated previously I have instrumented gam_data.c with the previously
> mentioned patch I can change the error to be.
> 


>From what I can tell, the error isn't directly related to inotify. When
inotify is enabled, a different poll backend is used for directories
that we don't want to use inotify on. My hunch is that the error is in
there.

> invalid length 10794 expected sizeof(GAMPacket) 4106 got 10794
> invalid length 10794 expected sizeof(GAMPacket) 4106 got 10794
> 
> My c experience tells me that sizeof is a compile time operator.  How do I find
> who is sending GAMPackets that are close to three times the size that they
> should be?
> 
> Is this any help?  If not please advise what further I need to do to
> produce useful output.


This isn't particularly helpful. 

Could you narrow down which application is receiving the fam errors? The
errors in the X log are from FAM clients (I think).

What filesystems are you using ? Inotify isn't being used for anything
inside your home directory, so inotify is basically watching some system
files (like /etc/mtab).

John