hook script piping to file has no content when borgmatic is run from cron #374

New Issue

shpokas · 2020-12-04T08:01:50Z

shpokas commented

2020-12-04 08:01:50 +00:00

What I'm trying to do and why

I am doing backups of KVM virtual machines using borgmatic and hook script.
The script creates VM snapshots and dumps VM configuration by piping "virsh dumpxml" command output to a file.
I am not sure at all this is borgmatic issue but when borgmatic is run from cron, created xml configuration files are empty.

To say that differently:
OK - hook script run from command line - xml dump files are created and have content.
OK - borgmatic run from command line - xml dump files are created and have content.
NOK - borgmatic run from cron - xml dump files are created but have zero size.

Steps to reproduce (if a bug)

borgmatic configuration:

location:
    source_directories:
        - /home
        - /etc
        - /var/log
        - /var/lib/libvirt/data
        - /var/lib/libvirt/images
        - /var/lib/libvirt/xml
    repositories:
        - /backup/local/borgrepo
        - /backup/nfs/borgrepo
storage:
retention:
    keep_daily: 5
    keep_weekly: 2
    keep_monthly: 2
consistency:
    check_last: 3
hooks:
    before_backup:
      - echo "Starting a backup."
      - /usr/local/sbin/vm_backup.sh snapshot
    before_prune:
      - echo "Starting pruning."
    before_check:
      - echo "Starting checks."
    before_extract:
      - echo "Starting extracting."
    after_backup:
      - echo "Finished a backup."
      - /usr/local/sbin/vm_backup.sh base
    after_prune:
      - echo "Finished pruning."
    after_check:
      - echo "Finished checks."
    after_extract:
      - echo "Finished extracting."
    on_error:
      - echo "Error during prune/create/check."

Part of the hook script - function that creates xml dumps:

export_vm_xml () {

  if [[ ! -d "${XMLBACKUPDIR}" ]] ; then
    mkdir -p "${XMLBACKUPDIR}" || error_exit "Could not create VM XML backup folder!" 9
  fi

  ${VIRSH} dumpxml --migratable "${1}" > "${XMLBACKUPDIR}/${1}.xml" || error_exit "Could not write VM XML backup file!" 10

}

cron job

cat /etc/cron.d/borgmatic 
# You can drop this file into /etc/cron.d/ to run borgmatic nightly.

50 9 * * * root PATH=$PATH:/usr/bin:/usr/sbin:/usr/local/bin:/usr/local/sbin /usr/local/bin/borgmatic --syslog-verbosity 1

Actual behavior (if a bug)

virsh dumpxml produces empty files when script is executed via cron.

If borgmatic is run from command line

#/usr/local/bin/borgmatic --syslog-verbosity 2
Starting pruning.
Starting a backup.
VM - tftp
Domain snapshot backup_20201204092954.qcow2 created
VM - sf
Domain snapshot backup_20201204092954.qcow2 created
VM - im-replica
Domain snapshot backup_20201204092954.qcow2 created
VM - im
Domain snapshot backup_20201204092954.qcow2 created
VM - tiger
Domain snapshot backup_20201204092954.qcow2 created
Starting checks.
^C

xml files have content:

ls -ltr /var/lib/libvirt/xml/
total 40
-rw-r--r--. 1 root root 4565 Dec 4 09:35 tftp.xml
-rw-r--r--. 1 root root 6791 Dec 4 09:35 sf.xml
-rw-r--r--. 1 root root 4522 Dec 4 09:35 im-replica.xml
-rw-r--r--. 1 root root 4386 Dec 4 09:35 im.xml
-rw-r--r--. 1 root root 6685 Dec 4 09:35 tiger.xml

If borgmatic is started from cron, then xml files are empty.

cron log

Dec 4 09:50:01 master CROND[13743]: (root) CMD (PATH=$PATH:/usr/bin:/usr/sbin:/usr/local/bin:/usr/local/sbin /usr/local/bin/borgmatic --syslog-verbosity 1)

syslog

Dec 4 09:50:02 master borgmatic: INFO /etc/borgmatic/config.yaml: Running command for pre-prune hook
Dec 4 09:50:02 master borgmatic: WARNING Starting pruning.
Dec 4 09:50:02 master borgmatic: INFO /etc/borgmatic/config.yaml: Running 2 commands for pre-backup hook
Dec 4 09:50:02 master borgmatic: WARNING Starting a backup.
Dec 4 09:50:02 master borgmatic: WARNING VM - tftp
Dec 4 09:50:02 master borgmatic: WARNING Domain snapshot backup_20201204095002.qcow2 created
Dec 4 09:50:02 master borgmatic: WARNING VM - sf
Dec 4 09:50:02 master borgmatic: WARNING Domain snapshot backup_20201204095002.qcow2 created
Dec 4 09:50:02 master borgmatic: WARNING VM - im-replica
Dec 4 09:50:03 master borgmatic: WARNING Domain snapshot backup_20201204095002.qcow2 created
Dec 4 09:50:03 master borgmatic: WARNING VM - im
Dec 4 09:50:03 master borgmatic: WARNING Domain snapshot backup_20201204095002.qcow2 created
Dec 4 09:50:03 master borgmatic: WARNING VM - tiger
Dec 4 09:50:03 master borgmatic: WARNING Domain snapshot backup_20201204095002.qcow2 created
Dec 4 09:50:03 master borgmatic: INFO /etc/borgmatic/config.yaml: Running command for pre-check hook
Dec 4 09:50:03 master borgmatic: WARNING Starting checks.
Dec 4 09:50:03 master borgmatic: INFO /backup/local/borgrepo: Pruning archives
Dec 4 09:50:04 master borgmatic: INFO /backup/local/borgrepo: Creating archive
Dec 4 09:50:05 master borgmatic: INFO Creating archive at "/backup/local/borgrepo::{hostname}-{now:%Y-%m-%dT%H:%M:%S.%f}"

but resulting files have 0 size

ls -ltr /var/lib/libvirt/xml/
total 0
-rw-r--r--. 1 root root 0 Dec 4 09:50 tftp.xml
-rw-r--r--. 1 root root 0 Dec 4 09:50 sf.xml
-rw-r--r--. 1 root root 0 Dec 4 09:50 im-replica.xml
-rw-r--r--. 1 root root 0 Dec 4 09:50 im.xml
-rw-r--r--. 1 root root 0 Dec 4 09:50 tiger.xml

Note that timestamps match cronjob execution time.

Expected behavior (if a bug)

xml files from virsh dumpxml command have content.

Other notes / implementation ideas

Environment

borgmatic version: 1.5.12

borgmatic installation method:

System-wide pip installation.

Borg version: borg 1.1.14

Python version: Python 3.6.8

Database version (if applicable): N/A

operating system and version: CentOS Linux release 7.9.2009 (Core)

#### What I'm trying to do and why I am doing backups of KVM virtual machines using borgmatic and hook script. The script creates VM snapshots and dumps VM configuration by piping "virsh dumpxml" command output to a file. I am not sure at all this is borgmatic issue but when borgmatic is **run from cron**, created xml configuration files are empty. To say that differently: OK - hook script run from command line - xml dump files are created and have content. OK - borgmatic run from command line - xml dump files are created and have content. NOK - borgmatic run from cron - xml dump files are created but **have zero size**. #### Steps to reproduce (if a bug) borgmatic configuration: ``` location: source_directories: - /home - /etc - /var/log - /var/lib/libvirt/data - /var/lib/libvirt/images - /var/lib/libvirt/xml repositories: - /backup/local/borgrepo - /backup/nfs/borgrepo storage: retention: keep_daily: 5 keep_weekly: 2 keep_monthly: 2 consistency: check_last: 3 hooks: before_backup: - echo "Starting a backup." - /usr/local/sbin/vm_backup.sh snapshot before_prune: - echo "Starting pruning." before_check: - echo "Starting checks." before_extract: - echo "Starting extracting." after_backup: - echo "Finished a backup." - /usr/local/sbin/vm_backup.sh base after_prune: - echo "Finished pruning." after_check: - echo "Finished checks." after_extract: - echo "Finished extracting." on_error: - echo "Error during prune/create/check." ``` Part of the hook script - function that creates xml dumps: ``` export_vm_xml () { if [[ ! -d "${XMLBACKUPDIR}" ]] ; then mkdir -p "${XMLBACKUPDIR}" || error_exit "Could not create VM XML backup folder!" 9 fi ${VIRSH} dumpxml --migratable "${1}" > "${XMLBACKUPDIR}/${1}.xml" || error_exit "Could not write VM XML backup file!" 10 } ``` cron job ``` cat /etc/cron.d/borgmatic # You can drop this file into /etc/cron.d/ to run borgmatic nightly. 50 9 * * * root PATH=$PATH:/usr/bin:/usr/sbin:/usr/local/bin:/usr/local/sbin /usr/local/bin/borgmatic --syslog-verbosity 1 ``` #### Actual behavior (if a bug) virsh dumpxml produces empty files when script is executed via cron. If borgmatic is run from command line > #/usr/local/bin/borgmatic --syslog-verbosity 2 > Starting pruning. > Starting a backup. > VM - tftp > Domain snapshot backup_20201204092954.qcow2 created > VM - sf > Domain snapshot backup_20201204092954.qcow2 created > VM - im-replica > Domain snapshot backup_20201204092954.qcow2 created > VM - im > Domain snapshot backup_20201204092954.qcow2 created > VM - tiger > Domain snapshot backup_20201204092954.qcow2 created > Starting checks. > ^C xml files have content: > ls -ltr /var/lib/libvirt/xml/ > total 40 > -rw-r--r--. 1 root root 4565 Dec 4 09:35 tftp.xml > -rw-r--r--. 1 root root 6791 Dec 4 09:35 sf.xml > -rw-r--r--. 1 root root 4522 Dec 4 09:35 im-replica.xml > -rw-r--r--. 1 root root 4386 Dec 4 09:35 im.xml > -rw-r--r--. 1 root root 6685 Dec 4 09:35 tiger.xml If borgmatic is started from cron, then xml files are empty. cron log > Dec 4 09:50:01 master CROND[13743]: (root) CMD (PATH=$PATH:/usr/bin:/usr/sbin:/usr/local/bin:/usr/local/sbin /usr/local/bin/borgmatic --syslog-verbosity 1) syslog > Dec 4 09:50:02 master borgmatic: INFO /etc/borgmatic/config.yaml: Running command for pre-prune hook > Dec 4 09:50:02 master borgmatic: WARNING Starting pruning. > Dec 4 09:50:02 master borgmatic: INFO /etc/borgmatic/config.yaml: Running 2 commands for pre-backup hook > Dec 4 09:50:02 master borgmatic: WARNING Starting a backup. > Dec 4 09:50:02 master borgmatic: WARNING VM - tftp > Dec 4 09:50:02 master borgmatic: WARNING Domain snapshot backup_20201204095002.qcow2 created > Dec 4 09:50:02 master borgmatic: WARNING VM - sf > Dec 4 09:50:02 master borgmatic: WARNING Domain snapshot backup_20201204095002.qcow2 created > Dec 4 09:50:02 master borgmatic: WARNING VM - im-replica > Dec 4 09:50:03 master borgmatic: WARNING Domain snapshot backup_20201204095002.qcow2 created > Dec 4 09:50:03 master borgmatic: WARNING VM - im > Dec 4 09:50:03 master borgmatic: WARNING Domain snapshot backup_20201204095002.qcow2 created > Dec 4 09:50:03 master borgmatic: WARNING VM - tiger > Dec 4 09:50:03 master borgmatic: WARNING Domain snapshot backup_20201204095002.qcow2 created > Dec 4 09:50:03 master borgmatic: INFO /etc/borgmatic/config.yaml: Running command for pre-check hook > Dec 4 09:50:03 master borgmatic: WARNING Starting checks. > Dec 4 09:50:03 master borgmatic: INFO /backup/local/borgrepo: Pruning archives > Dec 4 09:50:04 master borgmatic: INFO /backup/local/borgrepo: Creating archive > Dec 4 09:50:05 master borgmatic: INFO Creating archive at "/backup/local/borgrepo::{hostname}-{now:%Y-%m-%dT%H:%M:%S.%f}" **but resulting files have 0 size** > ls -ltr /var/lib/libvirt/xml/ > total 0 > -rw-r--r--. 1 root root 0 Dec 4 09:50 tftp.xml > -rw-r--r--. 1 root root 0 Dec 4 09:50 sf.xml > -rw-r--r--. 1 root root 0 Dec 4 09:50 im-replica.xml > -rw-r--r--. 1 root root 0 Dec 4 09:50 im.xml > -rw-r--r--. 1 root root 0 Dec 4 09:50 tiger.xml Note that timestamps match cronjob execution time. #### Expected behavior (if a bug) xml files from virsh dumpxml command have content. #### Other notes / implementation ideas #### Environment **borgmatic version:** 1.5.12 **borgmatic installation method:** System-wide pip installation. **Borg version:** borg 1.1.14 **Python version:** Python 3.6.8 **Database version (if applicable):** N/A **operating system and version:** CentOS Linux release 7.9.2009 (Core)

shpokas commented

2020-12-04 08:43:08 +00:00

And just when I spent an hour creatng this report I suddenly realized I have to check selinux logs. And bom - there I have related entries:
type=AVC msg=audit(1607068202.425:538902): avc: denied { write } for pid=13789 comm="virsh" path="/var/lib/libvirt/xml/tftp.xml" dev="dm-1" ino=21409 scontext=system_u:system_r:virsh_t:s0-s0:c0.c1023 tcontext=unconfined_u:object_r:unlabeled_t:s0 tclass=file permissive=0
type=AVC msg=audit(1607068202.548:538904): avc: denied { write } for pid=13916 comm="virsh" path="/var/lib/libvirt/xml/sf.xml" dev="dm-1" ino=21408 scontext=system_u:system_r:virsh_t:s0-s0:c0.c1023 tcontext=unconfined_u:object_r:unlabeled_t:s0 tclass=file permissive=0
type=AVC msg=audit(1607068202.943:538914): avc: denied { write } for pid=14015 comm="virsh" path="/var/lib/libvirt/xml/im-replica.xml" dev="dm-1" ino=2266431 scontext=system_u:system_r:virsh_t:s0-s0:c0.c1023 tcontext=unconfined_u:object_r:unlabeled_t:s0 tclass=file permissive=0
type=AVC msg=audit(1607068203.079:538916): avc: denied { write } for pid=14032 comm="virsh" path="/var/lib/libvirt/xml/im.xml" dev="dm-1" ino=20121 scontext=system_u:system_r:virsh_t:s0-s0:c0.c1023 tcontext=unconfined_u:object_r:unlabeled_t:s0 tclass=file permissive=0
type=AVC msg=audit(1607068203.213:538926): avc: denied { write } for pid=14050 comm="virsh" path="/var/lib/libvirt/xml/tiger.xml" dev="dm-1" ino=21421 scontext=system_u:system_r:virsh_t:s0-s0:c0.c1023 tcontext=unconfined_u:object_r:unlabeled_t:s0 tclass=file permissive=0

Please close this issue, it is not borgmatic, but selinux permission problem.

And just when I spent an hour creatng this report I suddenly realized I have to check selinux logs. And bom - there I have related entries: type=AVC msg=audit(1607068202.425:538902): avc: denied { write } for pid=13789 comm="virsh" path="/var/lib/libvirt/xml/tftp.xml" dev="dm-1" ino=21409 scontext=system_u:system_r:virsh_t:s0-s0:c0.c1023 tcontext=unconfined_u:object_r:unlabeled_t:s0 tclass=file permissive=0 type=AVC msg=audit(1607068202.548:538904): avc: denied { write } for pid=13916 comm="virsh" path="/var/lib/libvirt/xml/sf.xml" dev="dm-1" ino=21408 scontext=system_u:system_r:virsh_t:s0-s0:c0.c1023 tcontext=unconfined_u:object_r:unlabeled_t:s0 tclass=file permissive=0 type=AVC msg=audit(1607068202.943:538914): avc: denied { write } for pid=14015 comm="virsh" path="/var/lib/libvirt/xml/im-replica.xml" dev="dm-1" ino=2266431 scontext=system_u:system_r:virsh_t:s0-s0:c0.c1023 tcontext=unconfined_u:object_r:unlabeled_t:s0 tclass=file permissive=0 type=AVC msg=audit(1607068203.079:538916): avc: denied { write } for pid=14032 comm="virsh" path="/var/lib/libvirt/xml/im.xml" dev="dm-1" ino=20121 scontext=system_u:system_r:virsh_t:s0-s0:c0.c1023 tcontext=unconfined_u:object_r:unlabeled_t:s0 tclass=file permissive=0 type=AVC msg=audit(1607068203.213:538926): avc: denied { write } for pid=14050 comm="virsh" path="/var/lib/libvirt/xml/tiger.xml" dev="dm-1" ino=21421 scontext=system_u:system_r:virsh_t:s0-s0:c0.c1023 tcontext=unconfined_u:object_r:unlabeled_t:s0 tclass=file permissive=0 Please close this issue, it is not borgmatic, but selinux permission problem.

shpokas closed this issue

2020-12-04 08:43:08 +00:00

Sign in to join this conversation.