Automount script barfs

The place to post if you need help or advice

Moderators: ChrisThornett, LXF moderators

Automount script barfs

Postby Arthur_Dent » Thu Apr 24, 2014 5:02 pm

Hello All,

I thought I was so clever (pride comes before a fall).

I have created a backup script which rsyncs all my files to a second drive on the same machine and then tars and gzips them. The resultant file is about 5gb. I want to copy this onto a USB stick to keep in an alternate location. Wishing to avoid hassle I had the dream that I could simply plug in the USB stick and it would auto-mount and automatically copy the backup tar.gz and then - for good measure - send me a mail to tell me its all done.

It all works but for one thing. The mail gets sent 11 times each time I plug in the stick!

Here's what I did:
1) Created a moutpoint in /etc/fstab using the UUID of the stick:
Code: Select all
UUID=30B8-E25C        /mnt/USBBackup   vfat nofail,auto,noatime,rw 0 0

2) Wrote a udev rule (/etc/udev/rules.d/100-mount-myUSB.rules) for the stick:
Code: Select all
ACTION=="add", ATTRS{idVendor}=="8564", ATTRS{idProduct}=="1000", RUN+="/root/scripts/mount_USBBackup.sh"

3) Wrote the script to run when that exact USB stick is inserted:
Code: Select all
#!/bin/bash
#
# /root/scripts/mount_USBBackup.sh
# If this works, it should auto mount the USB stick and copy the backup files onto it...

SOURCEDIR=/mnt/BackupDrive/Backups
DESTDIR=/mnt/USBBackup
TESTFILE=rsync_logHome.log

SUBJECT="Backups Copied to USB Stick"
MAILFILE=/root/scripts/mount_USBBackup.mailfile
EMAIL=root

COPYLOG=/mnt/BackupDrive/copylog
TIMESTAMP=`date`

mount -a
sleep 1

cp $SOURCEDIR/$TESTFILE $DESTDIR

umount $DESTDIR

mailx -s "$SUBJECT" $EMAIL < $MAILFILE

echo "Backup files copied at $TIMESTAMP" >> $COPYLOG

As I say - everything works as hoped - but BOTH the mail and the logging function (which I only really added to the script as a test) are executed 11 times each.

Any idea why?

Thanks for any help!

Mark
Arthur_Dent
LXF regular
 
Posts: 219
Joined: Mon Jan 02, 2006 11:05 am
Location: London

Postby nelz » Thu Apr 24, 2014 6:45 pm

This could be because you are abusing udev, causing the script to run multiple times. From the RUN section of man udev

This can only be used for very short-running foreground tasks.


You need to set RUN to call a script that fires up your backup task in the background and then returns, otherwise you are making the whole of udev wait while your backup runs. You should also add an ACTION test to your udev rule so the script is only run when the stick is plugged in and not on every udev event.
"Insanity: doing the same thing over and over again and expecting different results." (Albert Einstein)
User avatar
nelz
Site admin
 
Posts: 8504
Joined: Mon Apr 04, 2005 11:52 am
Location: Warrington, UK

Postby Arthur_Dent » Thu Apr 24, 2014 9:57 pm

Hmm.. Thanks Nelz.

Have I misunderstood how udev works?

I used as a starting point this guide.

Note that I have used the specific ID number of the specific USB stick in question (8564:1000). I thought that the RUN command did simply fire up my script? Do I need to do something to tell it to run in the background?

Note also that the actual backup is not done by the script.
The idea behind this is that the backup (rsync of just about everything, followed by tar and gzip) takes place at 4am. The problem is that it is simply copying files from one physical HD to another HD in the same machine. A good backup if the drive fails - but what if there is a more dramatic problem with the machine? I have no (affordable) options for online or offsite storage.

What I had hoped to achieve was that every day I would simple pop this particular USB stick in and go away and have breakfast. The machine would detect that the USB stick had been inserted, mount the drive, copy the tar file(s) to it and then unmount. It would then send me a polite email to tell me it had finished and I would put the USB stick in my pocket and go off to work.

The script described below just does the copying of the tar file and the email.

How can I make this work?

Thanks again for your help...

Mark
Arthur_Dent
LXF regular
 
Posts: 219
Joined: Mon Jan 02, 2006 11:05 am
Location: London

Postby nelz » Thu Apr 24, 2014 10:19 pm

The udev man pages states that RUN should only be used for very short-running tasks, copying a large backup file to a USB stick does not fall into that category. The whole of udev is blocked while your script is running, with who knows what results.

You could have udev run "ude-backup.sh" which consists only of

Code: Select all
#!/bin/sh
nohup backupscript.sh &


which will return immediately.

Not only that, your script runs on any udev event involving that device, when you only want it to run on an add action, which is why I recommended using ACTION=="add".

The guide you followed is flawed in several ways, a much better guide is at http://www.reactivated.net/writing_udev_rules.html. Reading the udev man page is a good idea too.
"Insanity: doing the same thing over and over again and expecting different results." (Albert Einstein)
User avatar
nelz
Site admin
 
Posts: 8504
Joined: Mon Apr 04, 2005 11:52 am
Location: Warrington, UK

Postby Arthur_Dent » Thu Apr 24, 2014 10:28 pm

Hi Nelz,
That link 404s on me at the moment. I will try again in the morning...

I do have ACTION=="add" in my udev rule
Code: Select all
ACTION=="add", ATTRS{idVendor}=="8564", ATTRS{idProduct}=="1000", RUN+="/root/scripts/mount_USBBackup.sh"
Have I confused things by having that as well as RUN?

I will however try the script that hands-off to another script idea.

Thanks again for your help. Much appreciated...
Arthur_Dent
LXF regular
 
Posts: 219
Joined: Mon Jan 02, 2006 11:05 am
Location: London

Postby nelz » Thu Apr 24, 2014 10:42 pm

Drop the full stop at the end of the URL.

ACTION is a test, RUN is an assignment, you need both.
"Insanity: doing the same thing over and over again and expecting different results." (Albert Einstein)
User avatar
nelz
Site admin
 
Posts: 8504
Joined: Mon Apr 04, 2005 11:52 am
Location: Warrington, UK

Postby Arthur_Dent » Fri Apr 25, 2014 10:43 am

Well that Udev guide made interesting reading, but I am no nearer solving the problem.

My udev rule now reads:
Code: Select all
ACTION=="add", ATTRS{idVendor}=="8564", ATTRS{idProduct}=="1000", RUN+="/root/scripts/mount_USBStick1.sh"

and mount_USBStick1.sh reads:
Code: Select all
#!/bin/sh
nohup /root/scripts/mount_USBBackup.sh 1 &
and the mount_USBBackup.sh script is unchanged from my earlier posting (with the exception that I have made use of the argument passed by the script called by the udev rule to allow for different USB sticks to be used and the script will identify this from the argument).

Even though the script is no longer the direct result of the udev run command, I still get 11 emails and 12 writes to the log file!

Flummoxed...
Arthur_Dent
LXF regular
 
Posts: 219
Joined: Mon Jan 02, 2006 11:05 am
Location: London

Postby nelz » Fri Apr 25, 2014 10:58 am

What happens when you run the scripts manually? You could add a line to each script to log when it is running

Code: Select all
logger "running $0"


At least that way you will know what is being run 11 times. Also set "udev_log="info" in /etc/udev/udev.conf to get more details from udev itself.
"Insanity: doing the same thing over and over again and expecting different results." (Albert Einstein)
User avatar
nelz
Site admin
 
Posts: 8504
Joined: Mon Apr 04, 2005 11:52 am
Location: Warrington, UK

Postby Arthur_Dent » Fri Apr 25, 2014 11:40 am

Running mount_USBStick1.sh (which in turn calls mount_USBBackup.sh) from the command line produced;
Code: Select all
nohup: appending output to ‘nohup.out’
and the result of the logger calls in in /var/log/messages was simply:
Code: Select all
Apr 25 12:29:38 Zaphod mark: running ./mount_USBStick1.sh
Apr 25 12:29:38 Zaphod mark: running /root/scripts/mount_USBBackup.sh
This all works as expected; the copy gets performed and just one entry is written to my testing logfile and just one email is sent.

Taking the stick out and plugging it back in again produces:
Code: Select all
Apr 25 12:36:09 Zaphod kernel: usb-storage 2-5:1.0: USB Mass Storage device detected
Apr 25 12:36:09 Zaphod kernel: scsi20 : usb-storage 2-5:1.0
Apr 25 12:36:09 Zaphod kernel: [357420.913901] scsi 20:0:0:0: Direct-Access     JetFlash Transcend 32GB   8.07 PQ: 0 ANSI: 4
Apr 25 12:36:09 Zaphod kernel: [357420.914751] sd 20:0:0:0: Attached scsi generic sg3 type 0
Apr 25 12:36:09 Zaphod kernel: [357420.916015] sd 20:0:0:0: [sdc] 62750720 512-byte logical blocks: (32.1 GB/29.9 GiB)
Apr 25 12:36:09 Zaphod kernel: [357420.917137] sd 20:0:0:0: [sdc] Write Protect is off
Apr 25 12:36:09 Zaphod kernel: [357420.918263] sd 20:0:0:0: [sdc] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA
Apr 25 12:36:09 Zaphod kernel: [357420.923773]  sdc: sdc1
Apr 25 12:36:09 Zaphod kernel: [357420.927033] sd 20:0:0:0: [sdc] Attached SCSI removable disk
Apr 25 12:36:09 Zaphod kernel: scsi 20:0:0:0: Direct-Access     JetFlash Transcend 32GB   8.07 PQ: 0 ANSI: 4
Apr 25 12:36:10 Zaphod kernel: sd 20:0:0:0: Attached scsi generic sg3 type 0
Apr 25 12:36:10 Zaphod kernel: sd 20:0:0:0: [sdc] 62750720 512-byte logical blocks: (32.1 GB/29.9 GiB)
Apr 25 12:36:10 Zaphod kernel: sd 20:0:0:0: [sdc] Write Protect is off
Apr 25 12:36:10 Zaphod kernel: sd 20:0:0:0: [sdc] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA
Apr 25 12:36:10 Zaphod kernel: sdc: sdc1
Apr 25 12:36:10 Zaphod kernel: sd 20:0:0:0: [sdc] Attached SCSI removable disk
Apr 25 12:36:11 Zaphod logger: running /root/scripts/mount_USBStick1.sh
Apr 25 12:36:11 Zaphod logger: running /root/scripts/mount_USBBackup.sh
Apr 25 12:36:13 Zaphod logger: running /root/scripts/mount_USBStick1.sh
Apr 25 12:36:13 Zaphod logger: running /root/scripts/mount_USBBackup.sh
Apr 25 12:36:15 Zaphod logger: running /root/scripts/mount_USBStick1.sh
Apr 25 12:36:15 Zaphod logger: running /root/scripts/mount_USBStick1.sh
Apr 25 12:36:15 Zaphod logger: running /root/scripts/mount_USBBackup.sh
Apr 25 12:36:15 Zaphod logger: running /root/scripts/mount_USBBackup.sh
Apr 25 12:36:17 Zaphod logger: running /root/scripts/mount_USBStick1.sh
Apr 25 12:36:17 Zaphod logger: running /root/scripts/mount_USBBackup.sh
Apr 25 12:36:19 Zaphod logger: running /root/scripts/mount_USBStick1.sh
Apr 25 12:36:19 Zaphod logger: running /root/scripts/mount_USBStick1.sh
Apr 25 12:36:19 Zaphod logger: running /root/scripts/mount_USBBackup.sh
Apr 25 12:36:19 Zaphod logger: running /root/scripts/mount_USBStick1.sh
Apr 25 12:36:19 Zaphod logger: running /root/scripts/mount_USBStick1.sh
Apr 25 12:36:19 Zaphod logger: running /root/scripts/mount_USBBackup.sh
Apr 25 12:36:19 Zaphod logger: running /root/scripts/mount_USBBackup.sh
Apr 25 12:36:19 Zaphod logger: running /root/scripts/mount_USBBackup.sh
Apr 25 12:36:19 Zaphod logger: running /root/scripts/mount_USBStick1.sh
Apr 25 12:36:19 Zaphod logger: running /root/scripts/mount_USBBackup.sh
Apr 25 12:36:22 Zaphod logger: running /root/scripts/mount_USBStick1.sh
Apr 25 12:36:22 Zaphod logger: running /root/scripts/mount_USBBackup.sh
and the (now) usual 11 emails and 12 writes to my logfile...

Still flummoxed...
Arthur_Dent
LXF regular
 
Posts: 219
Joined: Mon Jan 02, 2006 11:05 am
Location: London

Postby nelz » Fri Apr 25, 2014 12:35 pm

So we know that udev is producing multiple triggers, which you will also be able to see by running "udevadm monitor" and plugging in the stick. You need to refine the match criteria to cut down on the matches, as a start I'd suggest adding SUBSYSTEM="scsi".
"Insanity: doing the same thing over and over again and expecting different results." (Albert Einstein)
User avatar
nelz
Site admin
 
Posts: 8504
Joined: Mon Apr 04, 2005 11:52 am
Location: Warrington, UK

Postby Arthur_Dent » Fri Apr 25, 2014 12:40 pm

There is some more weirdness going on.

The USB stick is mounted at /mnt/USBBackup.

The script umounts it once it has copied the files.

I have taken the stick out of the drive and it is on the desk in front of me.

Code: Select all
# ll /mnt/USBBackup/
total 648
-rw-r--r--. 1 root root 659633 Apr 25 13:19 rsync_logHome.log

Code: Select all
# umount /mnt/USBBackup/
umount: /mnt/USBBackup/: not mounted
But...
Code: Select all
# touch /mnt/USBBackup/test
# echo "Hello me" > /mnt/USBBackup/test
# cat /mnt/USBBackup/test
Hello me
# ll /mnt/USBBackup/
total 652
-rw-r--r--. 1 root root 659633 Apr 25 13:19 rsync_logHome.log
-rw-r--r--. 1 root root      9 Apr 25 13:34 test

Flummoxed is my middle name...
Arthur_Dent
LXF regular
 
Posts: 219
Joined: Mon Jan 02, 2006 11:05 am
Location: London

Postby Arthur_Dent » Fri Apr 25, 2014 12:46 pm

Our last posts crossed.

But here is the output of udevadm monitor. I only hope it means more to you than to me. I'm out of my depth now...
Code: Select all
# udevadm monitor SUBSYSTEM="scsi"
monitor will print the received events for:
UDEV - the event which udev sends out after rule processing
KERNEL - the kernel uevent

KERNEL[361475.243992] add      /devices/pci0000:00/0000:00:1d.7/usb2/2-5 (usb)
KERNEL[361475.245140] add      /devices/pci0000:00/0000:00:1d.7/usb2/2-5/2-5:1.0 (usb)
KERNEL[361475.245452] add      /devices/pci0000:00/0000:00:1d.7/usb2/2-5/2-5:1.0/host22 (scsi)
KERNEL[361475.245469] add      /devices/pci0000:00/0000:00:1d.7/usb2/2-5/2-5:1.0/host22/scsi_host/host22 (scsi_host)
KERNEL[361476.250342] add      /devices/pci0000:00/0000:00:1d.7/usb2/2-5/2-5:1.0/host22/target22:0:0 (scsi)
KERNEL[361476.250370] add      /devices/pci0000:00/0000:00:1d.7/usb2/2-5/2-5:1.0/host22/target22:0:0/22:0:0:0 (scsi)
KERNEL[361476.250384] add      /devices/pci0000:00/0000:00:1d.7/usb2/2-5/2-5:1.0/host22/target22:0:0/22:0:0:0/scsi_disk/22:0:0:0 (scsi_disk)
KERNEL[361476.250397] add      /devices/pci0000:00/0000:00:1d.7/usb2/2-5/2-5:1.0/host22/target22:0:0/22:0:0:0/scsi_device/22:0:0:0 (scsi_device)
KERNEL[361476.251259] add      /devices/pci0000:00/0000:00:1d.7/usb2/2-5/2-5:1.0/host22/target22:0:0/22:0:0:0/scsi_generic/sg3 (scsi_generic)
KERNEL[361476.251510] add      /devices/pci0000:00/0000:00:1d.7/usb2/2-5/2-5:1.0/host22/target22:0:0/22:0:0:0/bsg/22:0:0:0 (bsg)
KERNEL[361476.255378] add      /devices/virtual/bdi/8:32 (bdi)
UDEV  [361476.256842] add      /devices/virtual/bdi/8:32 (bdi)
KERNEL[361476.261000] add      /devices/pci0000:00/0000:00:1d.7/usb2/2-5/2-5:1.0/host22/target22:0:0/22:0:0:0/block/sdc (block)
KERNEL[361476.261050] add      /devices/pci0000:00/0000:00:1d.7/usb2/2-5/2-5:1.0/host22/target22:0:0/22:0:0:0/block/sdc/sdc1 (block)
UDEV  [361477.418062] add      /devices/pci0000:00/0000:00:1d.7/usb2/2-5 (usb)
UDEV  [361479.784504] add      /devices/pci0000:00/0000:00:1d.7/usb2/2-5/2-5:1.0 (usb)
UDEV  [361482.143540] add      /devices/pci0000:00/0000:00:1d.7/usb2/2-5/2-5:1.0/host22 (scsi)
UDEV  [361484.422119] add      /devices/pci0000:00/0000:00:1d.7/usb2/2-5/2-5:1.0/host22/target22:0:0 (scsi)
UDEV  [361484.652422] add      /devices/pci0000:00/0000:00:1d.7/usb2/2-5/2-5:1.0/host22/scsi_host/host22 (scsi_host)
UDEV  [361486.791050] add      /devices/pci0000:00/0000:00:1d.7/usb2/2-5/2-5:1.0/host22/target22:0:0/22:0:0:0 (scsi)
UDEV  [361489.232398] add      /devices/pci0000:00/0000:00:1d.7/usb2/2-5/2-5:1.0/host22/target22:0:0/22:0:0:0/scsi_generic/sg3 (scsi_generic)
UDEV  [361489.252514] add      /devices/pci0000:00/0000:00:1d.7/usb2/2-5/2-5:1.0/host22/target22:0:0/22:0:0:0/scsi_disk/22:0:0:0 (scsi_disk)
UDEV  [361489.256932] add      /devices/pci0000:00/0000:00:1d.7/usb2/2-5/2-5:1.0/host22/target22:0:0/22:0:0:0/bsg/22:0:0:0 (bsg)
UDEV  [361489.277177] add      /devices/pci0000:00/0000:00:1d.7/usb2/2-5/2-5:1.0/host22/target22:0:0/22:0:0:0/block/sdc (block)
UDEV  [361489.440696] add      /devices/pci0000:00/0000:00:1d.7/usb2/2-5/2-5:1.0/host22/target22:0:0/22:0:0:0/scsi_device/22:0:0:0 (scsi_device)
UDEV  [361491.640142] add      /devices/pci0000:00/0000:00:1d.7/usb2/2-5/2-5:1.0/host22/target22:0:0/22:0:0:0/block/sdc/sdc1 (block)

Arthur_Dent
LXF regular
 
Posts: 219
Joined: Mon Jan 02, 2006 11:05 am
Location: London

Postby nelz » Fri Apr 25, 2014 1:01 pm

The mount point still exists after the device is unmounted, you are just writng files to the root filesystem.

udevadm does show multiple add events for the stick, try the SYSTEM="scsi" suggestion to reduce the number of matches. With enough fine tuning you can end up with exactly one match.

BTW I wrote a tutorial on udev rules in LXF 165.
"Insanity: doing the same thing over and over again and expecting different results." (Albert Einstein)
User avatar
nelz
Site admin
 
Posts: 8504
Joined: Mon Apr 04, 2005 11:52 am
Location: Warrington, UK

Postby Arthur_Dent » Fri Apr 25, 2014 1:07 pm

nelz wrote:BTW I wrote a tutorial on udev rules in LXF 165.
Christmas 2012?
I can't remember what I read last Thursday!
OK - I'm reading it now...
Arthur_Dent
LXF regular
 
Posts: 219
Joined: Mon Jan 02, 2006 11:05 am
Location: London

Postby Arthur_Dent » Fri Apr 25, 2014 2:01 pm

Thanks for the LXF165 tip. A good read (as always!).

It prompted me to try a few things - but all to no avail.

Firstly, using the udevaadm info suggestion in your tutorial I ran
Code: Select all
udevadm info --attribute-walk --name /dev/sdc1 | less
As a result of that I changed the udev tests to read:
Code: Select all
ATTRS{idVendor}=="8564", ATTRS{serial}=="71519F31"
Thinking you can't get more specific than that.

Secondly I tried changing the RUN attribution, firstly to just RUN= (instead of RUN+=) and then to RUN:=

Thirdly I tried adding a "&" to the script call in the udev rule (even though the script it calls also detaches).

None of these things have made any difference.

My rule currently reads:
Code: Select all
ACTION=="add", ATTRS{idVendor}=="8564", ATTRS{serial}=="71519F31", RUN:="/root/scripts/mount_USBStick1.sh &"

Running udev monitor with the subsystem filter (have I got the syntax correct?) produces this:
Code: Select all
# udevadm monitor --subsystem-match="scsi"
monitor will print the received events for:
UDEV - the event which udev sends out after rule processing
KERNEL - the kernel uevent

KERNEL[364803.996168] remove   /devices/pci0000:00/0000:00:1d.7/usb2/2-6/2-6:1.0/host28/target28:0:0/28:0:0:0 (scsi)
KERNEL[364803.996197] remove   /devices/pci0000:00/0000:00:1d.7/usb2/2-6/2-6:1.0/host28/target28:0:0 (scsi)
KERNEL[364803.996217] remove   /devices/pci0000:00/0000:00:1d.7/usb2/2-6/2-6:1.0/host28 (scsi)
UDEV  [364804.004275] remove   /devices/pci0000:00/0000:00:1d.7/usb2/2-6/2-6:1.0/host28/target28:0:0/28:0:0:0 (scsi)
UDEV  [364804.004846] remove   /devices/pci0000:00/0000:00:1d.7/usb2/2-6/2-6:1.0/host28/target28:0:0 (scsi)
UDEV  [364804.005416] remove   /devices/pci0000:00/0000:00:1d.7/usb2/2-6/2-6:1.0/host28 (scsi)
KERNEL[364809.736018] add      /devices/pci0000:00/0000:00:1d.7/usb2/2-5/2-5:1.0/host29 (scsi)
KERNEL[364810.740211] add      /devices/pci0000:00/0000:00:1d.7/usb2/2-5/2-5:1.0/host29/target29:0:0 (scsi)
KERNEL[364810.740241] add      /devices/pci0000:00/0000:00:1d.7/usb2/2-5/2-5:1.0/host29/target29:0:0/29:0:0:0 (scsi)
UDEV  [364818.191384] add      /devices/pci0000:00/0000:00:1d.7/usb2/2-5/2-5:1.0/host29 (scsi)
UDEV  [364820.451166] add      /devices/pci0000:00/0000:00:1d.7/usb2/2-5/2-5:1.0/host29/target29:0:0 (scsi)
UDEV  [364822.816348] add      /devices/pci0000:00/0000:00:1d.7/usb2/2-5/2-5:1.0/host29/target29:0:0/29:0:0:0 (scsi)


But I'm not sure how that helps (everything still happens 12 times)...

Thanks again for all your help. I do appreciate it.

Mark
Arthur_Dent
LXF regular
 
Posts: 219
Joined: Mon Jan 02, 2006 11:05 am
Location: London

Next

Return to Help!

Who is online

Users browsing this forum: No registered users and 3 guests