Z2MQTT / Mosquitto disconnect during PBS scheduled backup

Configuration
, ,
1

Hi,
I’m having a backup problem and can’t seem to find the solution myself. Does anyone know where else to look?

Setup:
Host → PVE 7.1-10, fully updated

HA VM:
HomeAssistant in a VM (100) created with GitHub - whiskerz007/proxmox_hassos_install.
Zigbee USB stick: Slaesh’s CC2652RB stick (Vendor/Device ID mapping in VM)
core-2021.12.10
supervisor-2021.12.2
Home Assistant OS 7.1

PBS VM:
Pbs in a VM (102) excluded from backup schedule.
PBS 2.1-3 fully updated
Datastore: PBS_onsite, local disk in Host, WDC_WD20eads-00R6B0

Backup job in PVE:
Naamloos2

Problem:
Every time I backup with a schedule in PVE to PBS, Zigbee2MQTT seems to lose connection to the MQTT server (Mosquitto broker).
Naamloos

Addon Mosquitto broker (6.0.1) config:

logins: []
customize:
  active: false
  folder: mosquitto
certfile: fullchain.pem
keyfile: privkey.pem
require_certificate: false

Addon Zigbee2MQTT (1.22.2-1) config:

data_path: /config/zigbee2mqtt
external_converters: []
devices: devices.yaml
groups: groups.yaml
homeassistant: true
permit_join: false
mqtt:
  base_topic: zigbee2mqtt
  server: mqtt://core-mosquitto
  user: x
  password: x
serial:
  port: >-
    /dev/serial/by-id/usb-Silicon_Labs_slae.sh_cc2652rb_stick_-_slaesh_s_iot_stuff_00_12_4B_00_21_CC_4A_44-if00-port0
advanced:
  log_level: warn
  pan_id: 6756
  channel: 11
  network_key:
    - x
    - x
    - x
    - x
    - x
    - x
    - x
    - x
    - x
    - x
    - x
    - x
    - x
    - x
    - x
    - x
  availability_blocklist: []
  availability_passlist: []
device_options:
  legacy: false
blocklist: []
passlist: []
queue: {}
frontend:
  port: 8099
experimental: {}
availability: false
socat:
  enabled: false
  master: pty,raw,echo=0,link=/tmp/ttyZ2M,mode=777
  slave: tcp-listen:8485,keepalive,nodelay,reuseaddr,keepidle=1,keepintvl=1,keepcnt=5
  options: '-d -d'
  log: false

PBS log:


VMID	NAME	STATUS	TIME	SIZE	FILENAME
100	HassOS-Ova	OK	00:03:06	32.00GB	vm/100/2022-01-23T12:45:01Z
101	UbuntuServer-20.04	OK	00:00:34	50.00GB	vm/101/2022-01-23T12:48:07Z
103	Frigate	OK	00:00:14	2.36GB	ct/103/2022-01-23T12:48:41Z
TOTAL	00:03:56	84.36GB	


Detailed backup logs:

vzdump 103 101 100 --mailnotification always --mode snapshot --quiet 1 --storage PBS_onsite


100: 2022-01-23 13:45:01 INFO: Starting Backup of VM 100 (qemu)
100: 2022-01-23 13:45:01 INFO: status = running
100: 2022-01-23 13:45:01 INFO: VM Name: HassOS-Ova
100: 2022-01-23 13:45:01 INFO: include disk 'sata0' 'local-lvm:vm-100-disk-1' 32G
100: 2022-01-23 13:45:01 INFO: include disk 'efidisk0' 'local-lvm:vm-100-disk-0' 4M
100: 2022-01-23 13:45:01 INFO: backup mode: snapshot
100: 2022-01-23 13:45:01 INFO: ionice priority: 7
100: 2022-01-23 13:45:01 INFO: creating Proxmox Backup Server archive 'vm/100/2022-01-23T12:45:01Z'
100: 2022-01-23 13:45:01 INFO: issuing guest-agent 'fs-freeze' command
100: 2022-01-23 13:45:02 INFO: issuing guest-agent 'fs-thaw' command
100: 2022-01-23 13:45:02 INFO: started backup task '2d2d27a6-c4be-4941-bd08-9bee11c0b918'
100: 2022-01-23 13:45:02 INFO: resuming VM again
100: 2022-01-23 13:45:02 INFO: efidisk0: dirty-bitmap status: OK (drive clean)
100: 2022-01-23 13:45:02 INFO: sata0: dirty-bitmap status: OK (3.8 GiB of 32.0 GiB dirty)
100: 2022-01-23 13:45:02 INFO: using fast incremental mode (dirty-bitmap), 3.8 GiB dirty of 32.0 GiB total
100: 2022-01-23 13:45:05 INFO:  13% (516.0 MiB of 3.8 GiB) in 3s, read: 172.0 MiB/s, write: 170.7 MiB/s
100: 2022-01-23 13:45:08 INFO:  14% (568.0 MiB of 3.8 GiB) in 6s, read: 17.3 MiB/s, write: 17.3 MiB/s
100: 2022-01-23 13:45:11 INFO:  16% (644.0 MiB of 3.8 GiB) in 9s, read: 25.3 MiB/s, write: 25.3 MiB/s
100: 2022-01-23 13:45:14 INFO:  18% (720.0 MiB of 3.8 GiB) in 12s, read: 25.3 MiB/s, write: 25.3 MiB/s
100: 2022-01-23 13:45:17 INFO:  20% (792.0 MiB of 3.8 GiB) in 15s, read: 24.0 MiB/s, write: 24.0 MiB/s
100: 2022-01-23 13:45:20 INFO:  22% (868.0 MiB of 3.8 GiB) in 18s, read: 25.3 MiB/s, write: 25.3 MiB/s
100: 2022-01-23 13:45:23 INFO:  24% (932.0 MiB of 3.8 GiB) in 21s, read: 21.3 MiB/s, write: 21.3 MiB/s
100: 2022-01-23 13:45:26 INFO:  26% (1016.0 MiB of 3.8 GiB) in 24s, read: 28.0 MiB/s, write: 28.0 MiB/s
100: 2022-01-23 13:45:29 INFO:  28% (1.1 GiB of 3.8 GiB) in 27s, read: 22.7 MiB/s, write: 22.7 MiB/s
100: 2022-01-23 13:45:32 INFO:  29% (1.1 GiB of 3.8 GiB) in 30s, read: 21.3 MiB/s, write: 21.3 MiB/s
100: 2022-01-23 13:45:35 INFO:  30% (1.1 GiB of 3.8 GiB) in 33s, read: 6.7 MiB/s, write: 6.7 MiB/s
100: 2022-01-23 13:45:38 INFO:  32% (1.2 GiB of 3.8 GiB) in 36s, read: 24.0 MiB/s, write: 24.0 MiB/s
100: 2022-01-23 13:45:41 INFO:  34% (1.3 GiB of 3.8 GiB) in 39s, read: 24.0 MiB/s, write: 24.0 MiB/s
100: 2022-01-23 13:45:44 INFO:  35% (1.3 GiB of 3.8 GiB) in 42s, read: 21.3 MiB/s, write: 21.3 MiB/s
100: 2022-01-23 13:45:47 INFO:  37% (1.4 GiB of 3.8 GiB) in 45s, read: 25.3 MiB/s, write: 25.3 MiB/s
100: 2022-01-23 13:45:50 INFO:  39% (1.5 GiB of 3.8 GiB) in 48s, read: 21.3 MiB/s, write: 21.3 MiB/s
100: 2022-01-23 13:45:53 INFO:  40% (1.5 GiB of 3.8 GiB) in 51s, read: 14.7 MiB/s, write: 14.7 MiB/s
100: 2022-01-23 13:45:56 INFO:  41% (1.6 GiB of 3.8 GiB) in 54s, read: 14.7 MiB/s, write: 14.7 MiB/s
100: 2022-01-23 13:45:59 INFO:  43% (1.6 GiB of 3.8 GiB) in 57s, read: 24.0 MiB/s, write: 24.0 MiB/s
100: 2022-01-23 13:46:02 INFO:  45% (1.7 GiB of 3.8 GiB) in 1m, read: 26.7 MiB/s, write: 26.7 MiB/s
100: 2022-01-23 13:46:05 INFO:  46% (1.7 GiB of 3.8 GiB) in 1m 3s, read: 8.0 MiB/s, write: 8.0 MiB/s
100: 2022-01-23 13:46:09 INFO:  47% (1.8 GiB of 3.8 GiB) in 1m 7s, read: 9.0 MiB/s, write: 9.0 MiB/s
100: 2022-01-23 13:46:12 INFO:  49% (1.9 GiB of 3.8 GiB) in 1m 10s, read: 26.7 MiB/s, write: 26.7 MiB/s
100: 2022-01-23 13:46:15 INFO:  50% (1.9 GiB of 3.8 GiB) in 1m 13s, read: 21.3 MiB/s, write: 21.3 MiB/s
100: 2022-01-23 13:46:18 INFO:  52% (2.0 GiB of 3.8 GiB) in 1m 16s, read: 21.3 MiB/s, write: 21.3 MiB/s
100: 2022-01-23 13:46:21 INFO:  53% (2.0 GiB of 3.8 GiB) in 1m 19s, read: 14.7 MiB/s, write: 14.7 MiB/s
100: 2022-01-23 13:46:24 INFO:  55% (2.1 GiB of 3.8 GiB) in 1m 22s, read: 28.0 MiB/s, write: 28.0 MiB/s
100: 2022-01-23 13:46:27 INFO:  57% (2.2 GiB of 3.8 GiB) in 1m 25s, read: 18.7 MiB/s, write: 18.7 MiB/s
100: 2022-01-23 13:46:30 INFO:  58% (2.2 GiB of 3.8 GiB) in 1m 28s, read: 20.0 MiB/s, write: 20.0 MiB/s
100: 2022-01-23 13:46:33 INFO:  60% (2.3 GiB of 3.8 GiB) in 1m 31s, read: 18.7 MiB/s, write: 18.7 MiB/s
100: 2022-01-23 13:46:36 INFO:  62% (2.4 GiB of 3.8 GiB) in 1m 34s, read: 29.3 MiB/s, write: 29.3 MiB/s
100: 2022-01-23 13:46:39 INFO:  63% (2.4 GiB of 3.8 GiB) in 1m 37s, read: 13.3 MiB/s, write: 13.3 MiB/s
100: 2022-01-23 13:46:42 INFO:  64% (2.4 GiB of 3.8 GiB) in 1m 40s, read: 10.7 MiB/s, write: 10.7 MiB/s
100: 2022-01-23 13:46:45 INFO:  66% (2.5 GiB of 3.8 GiB) in 1m 43s, read: 22.7 MiB/s, write: 22.7 MiB/s
100: 2022-01-23 13:46:48 INFO:  67% (2.6 GiB of 3.8 GiB) in 1m 46s, read: 21.3 MiB/s, write: 21.3 MiB/s
100: 2022-01-23 13:46:51 INFO:  69% (2.6 GiB of 3.8 GiB) in 1m 49s, read: 22.7 MiB/s, write: 22.7 MiB/s
100: 2022-01-23 13:46:54 INFO:  71% (2.7 GiB of 3.8 GiB) in 1m 52s, read: 21.3 MiB/s, write: 21.3 MiB/s
100: 2022-01-23 13:46:57 INFO:  72% (2.7 GiB of 3.8 GiB) in 1m 55s, read: 13.3 MiB/s, write: 13.3 MiB/s
100: 2022-01-23 13:47:00 INFO:  75% (2.8 GiB of 3.8 GiB) in 1m 58s, read: 34.7 MiB/s, write: 34.7 MiB/s
100: 2022-01-23 13:47:03 INFO:  76% (2.9 GiB of 3.8 GiB) in 2m 1s, read: 14.7 MiB/s, write: 14.7 MiB/s
100: 2022-01-23 13:47:06 INFO:  77% (2.9 GiB of 3.8 GiB) in 2m 4s, read: 22.7 MiB/s, write: 22.7 MiB/s
100: 2022-01-23 13:47:09 INFO:  79% (3.0 GiB of 3.8 GiB) in 2m 7s, read: 22.7 MiB/s, write: 22.7 MiB/s
100: 2022-01-23 13:47:12 INFO:  81% (3.1 GiB of 3.8 GiB) in 2m 10s, read: 21.3 MiB/s, write: 21.3 MiB/s
100: 2022-01-23 13:47:16 INFO:  82% (3.1 GiB of 3.8 GiB) in 2m 14s, read: 9.0 MiB/s, write: 9.0 MiB/s
100: 2022-01-23 13:47:19 INFO:  83% (3.2 GiB of 3.8 GiB) in 2m 17s, read: 20.0 MiB/s, write: 20.0 MiB/s
100: 2022-01-23 13:47:22 INFO:  85% (3.2 GiB of 3.8 GiB) in 2m 20s, read: 18.7 MiB/s, write: 18.7 MiB/s
100: 2022-01-23 13:47:25 INFO:  87% (3.3 GiB of 3.8 GiB) in 2m 23s, read: 32.0 MiB/s, write: 32.0 MiB/s
100: 2022-01-23 13:47:28 INFO:  89% (3.4 GiB of 3.8 GiB) in 2m 26s, read: 16.0 MiB/s, write: 16.0 MiB/s
100: 2022-01-23 13:47:31 INFO:  91% (3.4 GiB of 3.8 GiB) in 2m 29s, read: 28.0 MiB/s, write: 28.0 MiB/s
100: 2022-01-23 13:47:34 INFO:  93% (3.5 GiB of 3.8 GiB) in 2m 32s, read: 26.7 MiB/s, write: 26.7 MiB/s
100: 2022-01-23 13:47:37 INFO:  95% (3.6 GiB of 3.8 GiB) in 2m 35s, read: 29.3 MiB/s, write: 29.3 MiB/s
100: 2022-01-23 13:47:40 INFO:  97% (3.7 GiB of 3.8 GiB) in 2m 38s, read: 18.7 MiB/s, write: 18.7 MiB/s
100: 2022-01-23 13:47:43 INFO:  99% (3.7 GiB of 3.8 GiB) in 2m 41s, read: 26.7 MiB/s, write: 26.7 MiB/s
100: 2022-01-23 13:47:46 INFO: 100% (3.8 GiB of 3.8 GiB) in 2m 44s, read: 10.7 MiB/s, write: 10.7 MiB/s
100: 2022-01-23 13:48:07 INFO: backup was done incrementally, reused 28.24 GiB (88%)
100: 2022-01-23 13:48:07 INFO: transferred 3.76 GiB in 185 seconds (20.8 MiB/s)
100: 2022-01-23 13:48:07 INFO: Finished Backup of VM 100 (00:03:06)

Zigbee2MQTT log:

[s6-init] making user provided files available at /var/run/s6/etc...exited 0.
[s6-init] ensuring user provided files have correct perms...exited 0.
[fix-attrs.d] applying ownership & permissions fixes...
[fix-attrs.d] done.
[cont-init.d] executing container initialization scripts...
[cont-init.d] socat.sh: executing... 
[13:12:27] INFO: Socat not enabled, marking service as down
[cont-init.d] socat.sh: exited 0.
[cont-init.d] zigbee2mqtt.sh: executing... 
[13:12:27] INFO: MQTT available, fetching server detail ...
[13:12:27] INFO: Previous config file found, checking backup
[13:12:27] INFO: Creating backup config in '/config/zigbee2mqtt/.configuration.yaml.bk'
[13:12:27] INFO: Adjusting Zigbee2mqtt core yaml config with add-on quirks ...
[cont-init.d] zigbee2mqtt.sh: exited 0.
[cont-init.d] done.
[services.d] starting services
[services.d] done.
[13:12:28] INFO: Handing over control to Zigbee2mqtt Core ...
> [email protected] start
> node index.js
Zigbee2MQTT:error 2022-01-23 13:47:01: Not connected to MQTT server!
Zigbee2MQTT:error 2022-01-23 13:47:01: Cannot send message: topic: 'zigbee2mqtt/gang_beganegrond_nachtlamp', payload: '{"current":0,"energy":2.12,"linkquality":102,"power":0,"power_outage_memory":"restore","state":"OFF","voltage":228}
Zigbee2MQTT:error 2022-01-23 13:47:01: Not connected to MQTT server!
Zigbee2MQTT:error 2022-01-23 13:47:01: Cannot send message: topic: 'zigbee2mqtt/gang_beganegrond_nachtlamp', payload: '{"current":0,"energy":2.12,"linkquality":138,"power":0,"power_outage_memory":"restore","state":"OFF","voltage":228}
Zigbee2MQTT:error 2022-01-23 13:47:01: Not connected to MQTT server!
Zigbee2MQTT:error 2022-01-23 13:47:01: Cannot send message: topic: 'zigbee2mqtt/garage_poort_verlichting', payload: '{"current":0,"energy":7.84,"linkquality":60,"power":0,"power_outage_memory":"off","state":"OFF","voltage":229}
Zigbee2MQTT:error 2022-01-23 13:47:01: Not connected to MQTT server!
Zigbee2MQTT:error 2022-01-23 13:47:01: Cannot send message: topic: 'zigbee2mqtt/garage_poort_verlichting', payload: '{"current":0,"energy":7.84,"linkquality":63,"power":0,"power_outage_memory":"off","state":"OFF","voltage":229}

Mosquitto broker log:

1642932915: Saving in-memory database to /data/mosquitto.db.
1642933236: Client mqttjs_8022ca15 disconnected.
1642933255: New connection from 172.30.32.1 on port 1883.
{"result": "ok", "data": {}}1642933255: New client connected from 172.30.32.1 as mqttjs_772a515c (p2, c1, k60, u'mqtt').
1642934503: Client mqttjs_772a515c has exceeded timeout, disconnecting.
1642934570: New connection from 172.30.32.1 on port 1883.
{"result": "ok", "data": {}}1642934570: New client connected from 172.30.32.1 as mqttjs_772a515c (p2, c1, k60, u'mqtt').
1642934716: Saving in-memory database to /data/mosquitto.db.
2

How does it behave when backing up with PVE?

4

Previously I used PVE to backup to a CIFS share on a Synology NAS. Never had a any problem with it.
Problems have started since I use PBS.

I just noticed, all devices disconnect when taking a backup:
Mosquitto broker:

1642940119: Saving in-memory database to /data/mosquitto.db.
1642941920: Saving in-memory database to /data/mosquitto.db.
1642941953: Client ESP8266Client-65b3 has exceeded timeout, disconnecting.
1642941953: New connection from 192.168.1.92 on port 1883.
{"result": "ok", "data": {}}1642941953: New client connected from 192.168.1.92 as ESP8266Client-fcb8 (p2, c1, k15, u'ArduinoMQTT').
1642941988: Client mqttjs_04ed7182 has exceeded timeout, disconnecting.
1642942022: New connection from 172.30.33.7 on port 1883.
{"result": "ok", "data": {}}1642942022: New client connected from 172.30.33.7 as mqttjs_04ed7182 (p2, c1, k60, u'mqtt').
1642943754: Saving in-memory database to /data/mosquitto.db.
1642945555: Saving in-memory database to /data/mosquitto.db.
1642945597: Client frigate has exceeded timeout, disconnecting.
1642945597: Client ESP8266Client-fcb8 has exceeded timeout, disconnecting.
1642945597: Client mqttjs_04ed7182 has exceeded timeout, disconnecting.
1642945597: New connection from 192.168.1.92 on port 1883.
5

IINM, PVE does a true snapshot while PBS uses more of a rsync approach. Seams like the supervisor/mqtt doesn’t like it. :man_shrugging:

6

Yeah, that’s what I thought too. Strange thing is that the outage takes place somewhere under the copy of the files.