Bug 1583457 - Using icrond to monitoring a NFS mount point
Summary: Using icrond to monitoring a NFS mount point
Keywords:
Status: ASSIGNED
Alias: None
Product: Fedora EPEL
Classification: Fedora
Component: incron
Version: epel7
Hardware: x86_64
OS: Linux
unspecified
low
Target Milestone: ---
Assignee: Kevin Fenzi
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2018-05-29 03:26 UTC by Nigel
Modified: 2020-11-03 18:54 UTC (History)
5 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2018-05-30 05:46:56 UTC
Type: Bug
Embargoed:

Attachments (Terms of Use)

Description Nigel 2018-05-29 03:26:53 UTC 
Description of problem:
We have noted that incron does not always pick up file changes on a monitored system if the file system is mounted after incron has been loaded.

I suspect there is  race condition here:

[12:05:18] root@npp-prod-was-13
/etc/systemd/system# systemctl status nfs-client.target
● nfs-client.target - NFS client services
   Loaded: loaded (/usr/lib/systemd/system/nfs-client.target; enabled; vendor preset: disabled)
   Active: active since Fri 2018-05-25 12:21:25 AEST; 3 days ago

May 25 12:21:25 npp-prod-was-13.creditlink.com.au systemd[1]: Reached target NFS client services.
May 25 12:21:25 npp-prod-was-13.creditlink.com.au systemd[1]: Starting NFS client services.

● incrond.service - Inotify System Scheduler
   Loaded: loaded (/usr/lib/systemd/system/incrond.service; enabled; vendor preset: disabled)
   Active: active (running) since Fri 2018-05-25 12:21:25 AEST; 3 days ago
Main PID: 689 (incrond)
   CGroup: /system.slice/incrond.service
           └─689 /usr/sbin/incrond

May 25 12:21:25 npp-prod-was-13.creditlink.com.au systemd[1]: Starting Inotify System Scheduler...
May 25 12:21:25 npp-prod-was-13.creditlink.com.au incrond[677]: starting service (version 0.5.10, built on Sep 24 2014 19:02:26)
May 25 12:21:25 npp-prod-was-13.creditlink.com.au incrond[689]: loading system tables
May 25 12:21:25 npp-prod-was-13.creditlink.com.au incrond[689]: loading user tables
May 25 12:21:25 npp-prod-was-13.creditlink.com.au incrond[689]: loading table for user wasadmin
May 25 12:21:25 npp-prod-was-13.creditlink.com.au incrond[689]: ready to process filesystem events
May 25 12:21:25 npp-prod-was-13.creditlink.com.au systemd[1]: Started Inotify System Scheduler.

as both are started the same time and I suspect incrond is starting up first before NFS.

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

nfs-utils-1.3.0-0.54.el7.x86_64
incron-0.5.10-8.el7.x86_64


How reproducible:
very


Steps to Reproduce:
incrontab entry:

/npp/import IN_CLOSE_WRITE /root/bin/nmm.sh $@/$#

Script contents
/root/bin# cat /root/bin/nmm.sh
#!/bin/bash
filename=$1
echo "$(date) Found File: $1" >> /tmp/nmm.junk 2>&1

Incron Running once loaded after NFS

[13:18:26] root@ibmsp-supp-02
/root/bin# echo "This is a test file" > /npp/import/nmm.junk
[13:18:28] root@ibmsp-supp-02
/root/bin# echo "This is a test file" > /npp/import/nmm.junk
[13:18:29] root@ibmsp-supp-02
/root/bin# echo "This is a test file" > /npp/import/nmm.junk
[13:18:30] root@ibmsp-supp-02
/root/bin# echo "This is a test file" > /npp/import/nmm.junk
[13:18:30] root@ibmsp-supp-02
/root/bin# echo "This is a test file" > /npp/import/nmm.junk
[13:18:32] root@ibmsp-supp-02
/root/bin# echo "This is a test file" > /npp/import/nmm.junk

Incron log entries:
2018-05-29T13:18:01.602113+10:00 ibmsp-supp-02 incrond[28133]: (root) CMD (/root/bin/nmm.sh /npp/import/nmm.junk)
2018-05-29T13:18:28.975097+10:00 ibmsp-supp-02 incrond[28133]: (root) CMD (/root/bin/nmm.sh /npp/import/nmm.junk)
2018-05-29T13:18:29.981485+10:00 ibmsp-supp-02 incrond[28133]: (root) CMD (/root/bin/nmm.sh /npp/import/nmm.junk)
2018-05-29T13:18:30.484573+10:00 ibmsp-supp-02 incrond[28133]: (root) CMD (/root/bin/nmm.sh /npp/import/nmm.junk)
2018-05-29T13:18:30.987448+10:00 ibmsp-supp-02 incrond[28133]: (root) CMD (/root/bin/nmm.sh /npp/import/nmm.junk)
2018-05-29T13:18:32.297748+10:00 ibmsp-supp-02 incrond[28133]: (root) CMD (/root/bin/nmm.sh /npp/import/nmm.junk)
2018-05-29T13:18:33.708373+10:00 ibmsp-supp-02 incrond[28133]: (root) CMD (/root/bin/nmm.sh /npp/import/nmm.junk)

Umount and remount NFS Share
[13:22:57] root@ibmsp-supp-02
/root/bin# umount /npp/import/

[13:23:06] root@ibmsp-supp-02
/root/bin# mount /npp/import/

Run test messages again
/root/bin# echo "This is a test file" > /npp/import/nmm.junk
[13:23:38] root@ibmsp-supp-02
/root/bin# echo "This is a test file" > /npp/import/nmm.junk
[13:23:39] root@ibmsp-supp-02
/root/bin# echo "This is a test file" > /npp/import/nmm.junk


Log file not updated
2018-05-29T13:18:33.708373+10:00 ibmsp-supp-02 incrond[28133]: (root) CMD (/root/bin/nmm.sh /npp/import/nmm.junk)
2018-05-29T13:18:52.758378+10:00 ibmsp-supp-02 incrond[28133]: (root) CMD (/root/bin/nmm.sh /npp/import/)
2018-05-29T13:18:52.758589+10:00 ibmsp-supp-02 incrond[28133]: (root) CMD (/root/bin/nmm.sh /npp/import/)

Entries from 13:23:37,38,39 not included in file
/root/bin# cat /tmp/nmm.junk
Found File: /npp/import/nmm.junk
Tue May 29 13:18:28 AEST 2018 Found File: /npp/import/nmm.junk
Tue May 29 13:18:29 AEST 2018 Found File: /npp/import/nmm.junk
Tue May 29 13:18:30 AEST 2018 Found File: /npp/import/nmm.junk
Tue May 29 13:18:30 AEST 2018 Found File: /npp/import/nmm.junk
Tue May 29 13:18:32 AEST 2018 Found File: /npp/import/nmm.junk
Tue May 29 13:18:33 AEST 2018 Found File: /npp/import/nmm.junk
Tue May 29 13:18:52 AEST 2018 Found File: /npp/import/
Tue May 29 13:18:52 AEST 2018 Found File: /npp/import/
[13:24:08] root@ibmsp-supp-02

Restart incrond
[13:24:58] root@ibmsp-supp-02
/root/bin# systemctl restart incrond


[13:25:20] root@ibmsp-supp-02
/root/bin# systemctl status incrond
● incrond.service - Inotify System Scheduler
   Loaded: loaded (/usr/lib/systemd/system/incrond.service; disabled; vendor preset: disabled)
   Active: active (running) since Tue 2018-05-29 13:25:09 AEST; 13s ago
  Process: 29263 ExecStart=/usr/sbin/incrond (code=exited, status=0/SUCCESS)
 Main PID: 29264 (incrond)
   CGroup: /system.slice/incrond.service
           └─29264 /usr/sbin/incrond


2018-05-29T13:25:09.599421+10:00 ibmsp-supp-02 incrond[28133]: stopping service
2018-05-29T13:25:09.608714+10:00 ibmsp-supp-02 incrond[29263]: starting service (version 0.5.10, built on Sep 24 2014 19:02:26)
2018-05-29T13:25:09.613623+10:00 ibmsp-supp-02 incrond[29264]: loading system tables
2018-05-29T13:25:09.613880+10:00 ibmsp-supp-02 incrond[29264]: loading user tables
2018-05-29T13:25:09.614776+10:00 ibmsp-supp-02 incrond[29264]: loading table for user spuser
2018-05-29T13:25:09.615332+10:00 ibmsp-supp-02 incrond[29264]: loading table for user root
2018-05-29T13:25:09.617126+10:00 ibmsp-supp-02 incrond[29264]: ready to process filesystem events


Send test messages:

[13:25:23] root@ibmsp-supp-02
/root/bin# echo "This is a test file" > /npp/import/nmm.junk
[13:25:32] root@ibmsp-supp-02
/root/bin# echo "This is a test file" > /npp/import/nmm.junk


Log file
2018-05-29T13:25:32.045328+10:00 ibmsp-supp-02 incrond[29264]: (root) CMD (/root/bin/nmm.sh /npp/import/nmm.junk)
2018-05-29T13:25:33.552584+10:00 ibmsp-supp-02 incrond[29264]: (root) CMD (/root/bin/nmm.sh /npp/import/nmm.junk)

File has new entries:

Tue May 29 13:25:32 AEST 2018 Found File: /npp/import/nmm.junk
Tue May 29 13:25:33 AEST 2018 Found File: /npp/import/nmm.junk



Actual results:
File changes are not picked up after file share is remounted.

Expected results:
File changes to be picked up.

Additional info:
Comment 2 Awez 2018-05-30 05:48:14 UTC 
Incron is UPSTREAM package not available in rhel repo
Comment 3 Nigel 2018-05-30 23:50:02 UTC 
This package comes from the EPEL Repo

root# yum info incron
Loaded plugins: versionlock
Installed Packages
Name        : incron
Arch        : x86_64
Version     : 0.5.10
Release     : 8.el7
Size        : 249 k
Repo        : installed
From repo   : epel
Summary     : Inotify cron system
URL         : http://inotify.aiken.cz
License     : GPLv2
Description : This program is an "inotify cron" system.
            : It consists of a daemon and a table manipulator.
            : You can use it a similar way as the regular cron.
            : The difference is that the inotify cron handles
            : filesystem events rather than time periods.

Please re-assign this to EPEL Fedora.
Comment 4 Kevin Fenzi 2018-05-31 16:14:16 UTC 
Can you try the scratch build at: 

https://koji.fedoraproject.org/koji/taskinfo?taskID=27191722

and see if it changes behavior any?
Comment 5 Nigel 2018-05-31 21:48:24 UTC 
Hi,

I am not sure what happened here but in my log file I see the following:

Tue May 29 13:25:32 AEST 2018 Found File: /import/nmm.junk
Tue May 29 13:25:33 AEST 2018 Found File: /import/nmm.junk
Fri Jun  1 07:39:33 AEST 2018 Found File: ./proc/1/task/1/fd/3/[timerfd]
Fri Jun  1 07:39:33 AEST 2018 Found File: ./proc/1/task/1/fd/3/[eventfd]
Fri Jun  1 07:39:33 AEST 2018 Found File: ./proc/1/task/1/fd/3/[eventpoll]
Fri Jun  1 07:39:33 AEST 2018 Found File: ./proc/1/task/1/fd/3/
Fri Jun  1 07:39:33 AEST 2018 Found File: ./proc/1/task/1/fd/3/
Fri Jun  1 07:39:33 AEST 2018 Found File: ./proc/1/task/1/fd/3/
Fri Jun  1 07:39:33 AEST 2018 Found File: ./proc/1/task/1/fd/3/
Fri Jun  1 07:39:33 AEST 2018 Found File: ./proc/1/task/1/fd/3/[eventpoll]
Fri Jun  1 07:39:33 AEST 2018 Found File: ./proc/1/task/1/fd/3/[eventpoll]
Fri Jun  1 07:39:33 AEST 2018 Found File: ./proc/1/task/1/fd/3/
Fri Jun  1 07:39:33 AEST 2018 Found File: ./proc/1/task/1/fd/3/[eventpoll]
Fri Jun  1 07:39:33 AEST 2018 Found File: ./dev/null


Which is strange because that seems to be more systems monitoring that I initially setup

/tmp# incrontab -l
/import IN_CLOSE_WRITE /root/bin/nmm.sh $@/$#

Cron log:

grep "2018-06-01T07:42:38" /var/log/cron

2018-06-01T07:42:38.180168+10:00 ibmsp-supp-02 incrond[2204]: PATH (./proc/1/task/1/fd/3) FILE ([eventpoll]) EVENT (IN_CLOSE_WRITE)
2018-06-01T07:42:38.180398+10:00 ibmsp-supp-02 incrond[2204]: (root) CMD (/root/bin/nmm.sh ./proc/1/task/1/fd/3/[eventpoll])
2018-06-01T07:42:38.180733+10:00 ibmsp-supp-02 incrond[2204]: PATH (./proc/1/task/1/fd/3) FILE () EVENT (IN_CLOSE_WRITE)
2018-06-01T07:42:38.180980+10:00 ibmsp-supp-02 incrond[2204]: (root) CMD (/root/bin/nmm.sh ./proc/1/task/1/fd/3/)
2018-06-01T07:42:38.183260+10:00 ibmsp-supp-02 incrond[2204]: PATH (./proc/1/task/1/fd/3) FILE ([eventpoll]) EVENT (IN_CLOSE_WRITE)
2018-06-01T07:42:38.183730+10:00 ibmsp-supp-02 incrond[2204]: (root) CMD (/root/bin/nmm.sh ./proc/1/task/1/fd/3/[eventpoll])
2018-06-01T07:42:38.186959+10:00 ibmsp-supp-02 incrond[2204]: PATH (./proc/1/task/1/fd/3) FILE () EVENT (IN_CLOSE_WRITE)
2018-06-01T07:42:38.188723+10:00 ibmsp-supp-02 incrond[2204]: (root) CMD (/root/bin/nmm.sh ./proc/1/task/1/fd/3/)
2018-06-01T07:42:38.295442+10:00 ibmsp-supp-02 incrond[2204]: PATH (./dev) FILE (tty) EVENT (IN_CLOSE_WRITE)
2018-06-01T07:42:38.295697+10:00 ibmsp-supp-02 incrond[2204]: (root) CMD (/root/bin/nmm.sh ./dev/tty)
2018-06-01T07:42:38.295963+10:00 ibmsp-supp-02 incrond[2204]: PATH (./dev/char/5:0) FILE () EVENT (IN_CLOSE_WRITE)
2018-06-01T07:42:38.296183+10:00 ibmsp-supp-02 incrond[2204]: (root) CMD (/root/bin/nmm.sh ./dev/char/5:0/)
2018-06-01T07:42:38.302918+10:00 ibmsp-supp-02 incrond[2204]: PATH (./dev) FILE (null) EVENT (IN_CLOSE_WRITE)
2018-06-01T07:42:38.303146+10:00 ibmsp-supp-02 incrond[2204]: (root) CMD (/root/bin/nmm.sh ./dev/null)
2018-06-01T07:42:38.305487+10:00 ibmsp-supp-02 incrond[2204]: PATH (./dev/char/1:3) FILE () EVENT (IN_CLOSE_WRITE)
2018-06-01T07:42:38.305728+10:00 ibmsp-supp-02 incrond[2204]: (root) CMD (/root/bin/nmm.sh ./dev/char/1:3/)
2018-06-01T07:42:38.499991+10:00 ibmsp-supp-02 incrond[2204]: stopping service

Thanks
-Nigel
Comment 6 Nigel 2018-05-31 21:52:25 UTC 
The log file is also full of the following:

2018-06-01T07:51:07.108603+10:00 ibmsp-supp-02 incrond[3761]: cannot create watch for user root: (28) No space left on device
2018-06-01T07:51:07.108852+10:00 ibmsp-supp-02 incrond[3761]: cannot create watch for user root: (28) No space left on device
2018-06-01T07:51:07.109099+10:00 ibmsp-supp-02 incrond[3761]: cannot create watch for user root: (28) No space left on device
2018-06-01T07:51:07.109350+10:00 ibmsp-supp-02 incrond[3761]: cannot create watch for user root: (28) No space left on device
2018-06-01T07:51:07.109608+10:00 ibmsp-supp-02 incrond[3761]: cannot create watch for user root: (28) No space left on device
2018-06-01T07:51:07.109854+10:00 ibmsp-supp-02 incrond[3761]: cannot create watch for user root: (28) No space left on device
2018-06-01T07:51:07.110099+10:00 ibmsp-supp-02 incrond[3761]: cannot create watch for user root: (28) No space left on device
2018-06-01T07:51:07.110342+10:00 ibmsp-supp-02 incrond[3761]: cannot create watch for user root: (28) No space left on device
2018-06-01T07:51:07.110720+10:00 ibmsp-supp-02 incrond[3761]: cannot create watch for user root: (28) No space left on device
2018-06-01T07:51:07.110978+10:00 ibmsp-supp-02 incrond[3761]: cannot create watch for user root: (28) No space left on device
2018-06-01T07:51:07.111228+10:00 ibmsp-supp-02 incrond[3761]: cannot create watch for user root: (28) No space left on device
2018-06-01T07:51:07.111480+10:00 ibmsp-supp-02 incrond[3761]: cannot create watch for user root: (28) No space left on device
(END)
Note You need to log in before you can comment on or make changes to this bug.