search

framps / raspiBackup

Create and keep multiple backup versions of your running Raspberries
https://raspibackup.linux-tips-and-tricks.de
GNU General Public License v3.0
809 stars 74 forks source link

raspiBackup stopping networking #641

Closed p1r473 closed 1 year ago

p1r473 commented 1 year ago

Hey Framp! Got a weird one today.

One of my Pis keeps losing networking but only after doing a raspiBackup restore. The restore sems to be successful, followed shortly by a reboot. I have the reboot function disabled in my config I also am not stopping any networking services

# reboot system at end of backup
DEFAULT_REBOOT_SYSTEM=0

I've checked the logs and found the culprit: raspiBackup.log syslog.log

The loss of networking triggers a reboot due to my watchdog (which I want).

Mar 27 20:40:47 Monkeebutt watchdog[1711]: device eth0 did not receive anything since last check
Mar 27 20:40:48 Monkeebutt watchdog[1711]: device eth0 did not receive anything since last check
Mar 27 20:41:01 Monkeebutt watchdog[1711]: message repeated 13 times: [ device eth0 did not receive anything since last check]
Mar 27 20:41:02 Monkeebutt watchdog[1711]: device eth0 did not receive anything since last check
Mar 27 20:41:07 Monkeebutt watchdog[1711]: message repeated 5 times: [ device eth0 did not receive anything since last check]
Mar 27 20:41:07 Monkeebutt watchdog[1711]: Retry timed-out at 61 seconds for eth0
Mar 27 20:41:07 Monkeebutt watchdog[1711]: shutting down the system because of error 101 = 'Network is unreachable'

But why does doing a raspiBackup restore seem to knock out networking? Im restoring a backup to /dev/sdb through a USB card reader plugged into a Pi 4 8gb.

This is on a different Pi than #640 and #620. This Pi is on a wired connection.

Separate question I am sneaking in here, how do you use DEFAULT_SKIPLOCALCHECK?

p1r473 commented 1 year ago

The eth0 network adapter funny business is happening EXACTLY RIGHT AFTER as soon as the restore is done. See the red square at the bottom right window. Also I know eth0 isnt actually down because a. Im SSHed in over it b. pings are still happening

image

Look closer to /var/log/syslog:

Mar 27 21:40:12 Monkeebutt watchdog[1909]: message repeated 10 times: [ device eth0 did not receive anyt                                                                                                           hing since last check]
Mar 27 21:40:13 Monkeebutt systemd[1610]: tmp-raspiBackup.mount: Succeeded.
Mar 27 21:40:13 Monkeebutt systemd[1489]: tmp-raspiBackup.mount: Succeeded.
Mar 27 21:40:13 Monkeebutt systemd[1]: tmp-raspiBackup.mount: Succeeded.
Mar 27 21:40:13 Monkeebutt watchdog[1909]: device eth0 did not receive anything since last check
Mar 27 21:40:39 Monkeebutt kernel: [ 3543.299049] EXT4-fs (sdb2): unmounting filesystem.
Mar 27 21:40:39 Monkeebutt kernel: [ 3543.698533] EXT4-fs (sdb2): mounted filesystem with ordered data m                                                                                                           ode. Quota mode: none.
Mar 27 21:40:40 Monkeebutt kernel: [ 3544.024569] EXT4-fs (sdb2): unmounting filesystem.
Mar 27 21:40:39 Monkeebutt watchdog[1909]: message repeated 26 times: [ device eth0 did not receive anyt                                                                                                           hing since last check]
Mar 27 21:40:40 Monkeebutt systemd[1489]: tmp-raspiBackup.mount: Succeeded.
Mar 27 21:40:40 Monkeebutt systemd[1610]: tmp-raspiBackup.mount: Succeeded.
Mar 27 21:40:40 Monkeebutt systemd[1]: tmp-raspiBackup.mount: Succeeded.
Mar 27 21:40:40 Monkeebutt kernel: [ 3544.527569] FAT-fs (sdb1): Volume was not properly unmounted. Some                                                                                                            data may be corrupt. Please run fsck.
Mar 27 21:40:40 Monkeebutt watchdog[1909]: device eth0 did not receive anything since last check
Mar 27 21:40:41 Monkeebutt kernel: [ 3544.749542] EXT4-fs (sdb2): mounted filesystem with ordered data m                                                                                                           ode. Quota mode: none.
Mar 27 21:40:41 Monkeebutt systemd[1610]: tmp-boot.mount: Succeeded.
Mar 27 21:40:41 Monkeebutt systemd[1]: tmp-boot.mount: Succeeded.
Mar 27 21:40:41 Monkeebutt systemd[1489]: tmp-boot.mount: Succeeded.
Mar 27 21:40:41 Monkeebutt systemd[1489]: tmp-root.mount: Succeeded.
Mar 27 21:40:41 Monkeebutt systemd[1]: tmp-root.mount: Succeeded.
Mar 27 21:40:41 Monkeebutt systemd[1610]: tmp-root.mount: Succeeded.
Mar 27 21:40:41 Monkeebutt kernel: [ 3545.015710] EXT4-fs (sdb2): unmounting filesystem.
Mar 27 21:40:41 Monkeebutt raspiBackup: Stopped 0.6.8 (4b9c22a). rc 0
Mar 27 21:40:41 Monkeebutt watchdog[1909]: device eth0 did not receive anything since last check
Mar 27 21:40:42 Monkeebutt watchdog[1909]: device eth0 did not receive anything since last check
Mar 27 21:40:43 Monkeebutt watchdog[1909]: device eth0 did not receive anything since last check
Mar 27 21:41:00 Monkeebutt watchdog[1909]: message repeated 17 times: [ device eth0 did not receive anyt                                                                                                           hing since last check]
Mar 27 21:41:01 Monkeebutt watchdog[1909]: device eth0 did not receive anything since last check
Mar 27 21:41:01 Monkeebutt watchdog[1909]: Retry timed-out at 61 seconds for eth0
Mar 27 21:41:01 Monkeebutt watchdog[1909]: shutting down the system because of error 101 = 'Network is u                                                                                                           nreachable'
p1r473 commented 1 year ago

I can replicate this 100% everytime right now. I've done this restore 20 times and each time I get a reboot from Watchdog due to loss of networking. Its only happening right after a restore, and not a backup, and not any other time

p1r473 commented 1 year ago

I just tried the restore on a whole different Pi and the exact same thing happens

Which leads me to believe its actually MAY be a raspiBackup issue syslog.log raspiBackup.log

framps commented 1 year ago

But why does doing a raspiBackup restore seem to knock out networking?

Good question. You're the first one who reports this kind of issue. As far as I can see it's somehow related to the watchdog because the watchdog detects there is no network connectivity any more and restarts the system. I have no experience with watchdog.

I checked the logs and found there are networking issues already when raspiBackup started and rwhod writes

Mar 27 22:05:32 Harbormaster rwhod[1040]: sending on interface eth0

twice and then the watchdog complaints about missing network connectivity.

Mar 27 22:02:32 Harbormaster rwhod[1040]: sending on interface eth0
Mar 27 22:02:50 Harbormaster hass[988]: 2023-03-27 22:02:50.012 ERROR (MainThread) [async_upnp_client.ssdp] Received error: [Errno 19] No such device, transport: <_SelectorDatagramTransport fd=18 read=polling write=<idle, bufsize=0>>, socket: <asyncio.TransportSocket fd=18, family=AddressFamily.AF_INET, type=SocketKind.SOCK_DGRAM, proto=0, laddr=('0.0.0.0', 60014)>
Mar 27 22:02:50 Harbormaster hass[988]: 2023-03-27 22:02:50.064 ERROR (MainThread) [async_upnp_client.ssdp] Received error: [Errno 19] No such device, transport: <_SelectorDatagramTransport fd=23 read=polling write=<idle, bufsize=0>>, socket: <asyncio.TransportSocket fd=23, family=AddressFamily.AF_INET, type=SocketKind.SOCK_DGRAM, proto=0, laddr=('0.0.0.0', 36025)>
Mar 27 22:03:20 Harbormaster hass[988]: 2023-03-27 22:03:20.066 ERROR (MainThread) [async_upnp_client.ssdp] Received error: [Errno 19] No such device, transport: <_SelectorDatagramTransport fd=23 read=polling write=<idle, bufsize=0>>, socket: <asyncio.TransportSocket fd=23, family=AddressFamily.AF_INET, type=SocketKind.SOCK_DGRAM, proto=0, laddr=('0.0.0.0', 36025)>
Mar 27 22:03:50 Harbormaster hass[988]: 2023-03-27 22:03:50.069 ERROR (MainThread) [async_upnp_client.ssdp] Received error: [Errno 19] No such device, transport: <_SelectorDatagramTransport fd=23 read=polling write=<idle, bufsize=0>>, socket: <asyncio.TransportSocket fd=23, family=AddressFamily.AF_INET, type=SocketKind.SOCK_DGRAM, proto=0, laddr=('0.0.0.0', 36025)>
Mar 27 22:04:20 Harbormaster hass[988]: 2023-03-27 22:04:20.071 ERROR (MainThread) [async_upnp_client.ssdp] Received error: [Errno 19] No such device, transport: <_SelectorDatagramTransport fd=23 read=polling write=<idle, bufsize=0>>, socket: <asyncio.TransportSocket fd=23, family=AddressFamily.AF_INET, type=SocketKind.SOCK_DGRAM, proto=0, laddr=('0.0.0.0', 36025)>
Mar 27 22:04:50 Harbormaster hass[988]: 2023-03-27 22:04:50.013 ERROR (MainThread) [async_upnp_client.ssdp] Received error: [Errno 19] No such device, transport: <_SelectorDatagramTransport fd=18 read=polling write=<idle, bufsize=0>>, socket: <asyncio.TransportSocket fd=18, family=AddressFamily.AF_INET, type=SocketKind.SOCK_DGRAM, proto=0, laddr=('0.0.0.0', 60014)>
Mar 27 22:04:50 Harbormaster hass[988]: 2023-03-27 22:04:50.074 ERROR (MainThread) [async_upnp_client.ssdp] Received error: [Errno 19] No such device, transport: <_SelectorDatagramTransport fd=23 read=polling write=<idle, bufsize=0>>, socket: <asyncio.TransportSocket fd=23, family=AddressFamily.AF_INET, type=SocketKind.SOCK_DGRAM, proto=0, laddr=('0.0.0.0', 36025)>
Mar 27 22:05:20 Harbormaster hass[988]: 2023-03-27 22:05:20.077 ERROR (MainThread) [async_upnp_client.ssdp] Received error: [Errno 19] No such device, transport: <_SelectorDatagramTransport fd=23 read=polling write=<idle, bufsize=0>>, socket: <asyncio.TransportSocket fd=23, family=AddressFamily.AF_INET, type=SocketKind.SOCK_DGRAM, proto=0, laddr=('0.0.0.0', 36025)>
Mar 27 22:05:32 Harbormaster rwhod[1040]: sending on interface eth0
Mar 27 22:05:50 Harbormaster hass[988]: 2023-03-27 22:05:50.078 ERROR (MainThread) [async_upnp_client.ssdp] Received error: [Errno 19] No such device, transport: <_SelectorDatagramTransport fd=23 read=polling write=<idle, bufsize=0>>, socket: <asyncio.TransportSocket fd=23, family=AddressFamily.AF_INET, type=SocketKind.SOCK_DGRAM, proto=0, laddr=('0.0.0.0', 36025)>
Mar 27 22:05:54 Harbormaster pulseway: Failed to collect BiosData for assets report
Mar 27 22:06:20 Harbormaster hass[988]: 2023-03-27 22:06:20.081 ERROR (MainThread) [async_upnp_client.ssdp] Received error: [Errno 19] No such device, transport: <_SelectorDatagramTransport fd=23 read=polling write=<idle, bufsize=0>>, socket: <asyncio.TransportSocket fd=23, family=AddressFamily.AF_INET, type=SocketKind.SOCK_DGRAM, proto=0, laddr=('0.0.0.0', 36025)>
Mar 27 22:06:50 Harbormaster hass[988]: 2023-03-27 22:06:50.014 ERROR (MainThread) [async_upnp_client.ssdp] Received error: [Errno 19] No such device, transport: <_SelectorDatagramTransport fd=18 read=polling write=<idle, bufsize=0>>, socket: <asyncio.TransportSocket fd=18, family=AddressFamily.AF_INET, type=SocketKind.SOCK_DGRAM, proto=0, laddr=('0.0.0.0', 60014)>
Mar 27 22:06:50 Harbormaster hass[988]: 2023-03-27 22:06:50.085 ERROR (MainThread) [async_upnp_client.ssdp] Received error: [Errno 19] No such device, transport: <_SelectorDatagramTransport fd=23 read=polling write=<idle, bufsize=0>>, socket: <asyncio.TransportSocket fd=23, family=AddressFamily.AF_INET, type=SocketKind.SOCK_DGRAM, proto=0, laddr=('0.0.0.0', 36025)>
Mar 27 22:07:20 Harbormaster hass[988]: 2023-03-27 22:07:20.088 ERROR (MainThread) [async_upnp_client.ssdp] Received error: [Errno 19] No such device, transport: <_SelectorDatagramTransport fd=23 read=polling write=<idle, bufsize=0>>, socket: <asyncio.TransportSocket fd=23, family=AddressFamily.AF_INET, type=SocketKind.SOCK_DGRAM, proto=0, laddr=('0.0.0.0', 36025)>
Mar 27 22:07:50 Harbormaster hass[988]: 2023-03-27 22:07:50.090 ERROR (MainThread) [async_upnp_client.ssdp] Received error: [Errno 19] No such device, transport: <_SelectorDatagramTransport fd=23 read=polling write=<idle, bufsize=0>>, socket: <asyncio.TransportSocket fd=23, family=AddressFamily.AF_INET, type=SocketKind.SOCK_DGRAM, proto=0, laddr=('0.0.0.0', 36025)>
Mar 27 22:07:55 Harbormaster watchdog[2566]: device eth0 did not receive anything since last check

I don't know rwhod. But for me rwhod causes the networking issue and the reason the watchdog restarts the system right after raspiBackup finishes the restore is by coincidence. Keep in mind the message was already written before multiple times. Maybe there is some watchdog configuration which defines how many Mar 27 22:07:55 Harbormaster watchdog[2566]: device eth0 did not receive anything since last check messages will be tolerated until the watchdog restarts the system.

raspiBackup doesn't do anything special in the networking area and thus I don't think raspiBackup causes the issue.

Separate question I am sneaking in here, how do you use DEFAULT_SKIPLOCALCHECK?

raspiBackup checks whether the backup mount point has an external partition mounted. Otherwise the backup is rejected with an error message. A backup to the root filesystem doesn't make sense and if you have a small SD card you may even blow up your system. This setting disables the check. I had some raspiBackup users who wanted to be able to backup to the root partition because they had a special setup: They create the local backup fast and then in another task this backup was xferred to external nfs storage which takes much longer. That way the time services had to be stopped was reduced to a minimum.

p1r473 commented 1 year ago

This is so bizarre that its happening on 2 different Pis It happens almost exactly as soon as the restore finishes Ive circled the timestamps when the issue starts and when the restore finishes

image image

p1r473 commented 1 year ago

Its weird because it only happens after a raspiBackup restore

cat /etc/watchdog.conf | grep -Pv '^#'

admin                   = root
interval                = 10
logtick                 = 1
log-dir                 = /var/log/watchdog
watchdog-device         = /dev/watchdog
max-temperature         = 85
watchdog-timeout        = 15
temperature-sensor      = /sys/class/thermal/thermal_zone0/temp
realtime                = yes
priority                = 1
interface               = eth0
ping-count              = 10
ping                    = 192.168.1.1
verbose                 = 2

grep watch /boot/config.txt

dtparam=watchdog=on

Might be related to https://github.com/RPi-Distro/repo/issues/237

p1r473 commented 1 year ago

Framp, if you find time, maybe you can install watchdog to test too?

apt install watchdog

My config is above.

p1r473 commented 1 year ago

I bet the unmounting is causing this I did see unmounts in the logs right before this happened And I am restoring from a Windows server Look what happens right before the issue starts. raspiBackup unmounts file system image

Look what happens right before the first error: EXT4-fs (sdb2): mounted filesystem with ordered data mode. Quota mode: none.

Mar 27 22:00:01 Harbormaster systemd[1]: Mounted Arbitrary Executable File Formats File System.
Mar 27 22:00:01 Harbormaster kernel: [  223.523760] EXT4-fs (sdb2): mounted filesystem with ordered data mode. Quota mode: none.
Mar 27 22:05:32 Harbormaster rwhod[1040]: sending on interface eth0
Mar 27 22:05:54 Harbormaster pulseway: Failed to collect BiosData for assets report
Mar 27 22:07:55 Harbormaster watchdog[2566]: device eth0 did not receive anything since last check

Look at all the mount activity before this starts:


Mar 27 21:59:13 Harbormaster root: cleared logs
Mar 27 21:59:19 Harbormaster systemd[1]: mnt-Monkeebutt.automount: Got automount request for /mnt/Monkeebutt, triggered by 4156 (zsh)
Mar 27 21:59:19 Harbormaster systemd[1]: Mounting /mnt/Monkeebutt...
Mar 27 21:59:19 Harbormaster kernel: [  181.413832] Key type cifs.spnego registered
Mar 27 21:59:19 Harbormaster kernel: [  181.413852] Key type cifs.idmap registered
Mar 27 21:59:19 Harbormaster kernel: [  181.415970] CIFS: Attempting to mount \\BLACKPEARL\Monkeebutt
Mar 27 21:59:19 Harbormaster systemd[1]: Mounted /mnt/Monkeebutt.
Mar 27 21:59:22 Harbormaster raspiBackup.sh: Started 0.6.8 (4b9c22a)
Mar 27 21:59:25 Harbormaster kernel: [  187.627806]  sdb: sdb1 sdb2
Mar 27 21:59:29 Harbormaster kernel: [  191.714876]  sdb: sdb1 sdb2
Mar 27 21:59:30 Harbormaster kernel: [  192.237512]  sdb: sdb1 sdb2
Mar 27 21:59:30 Harbormaster kernel: [  192.243397]  sdb: sdb1 sdb2
Mar 27 21:59:32 Harbormaster rwhod[1040]: sending on interface eth0
Mar 27 21:59:33 Harbormaster kernel: [  195.537946]  sdb: sdb1 sdb2
Mar 27 21:59:58 Harbormaster kernel: [  220.031298]  sdb: sdb1 sdb2
Mar 27 22:00:01 Harbormaster systemd[1]: mnt-Harbormaster.automount: Got automount request for /mnt/Harbormaster, triggered by 6305 (pydf)
Mar 27 22:00:01 Harbormaster systemd[1]: Mounting /mnt/Harbormaster...
Mar 27 22:00:01 Harbormaster kernel: [  223.341860] CIFS: Attempting to mount \\BLACKPEARL\Harbormaster
Mar 27 22:00:01 Harbormaster systemd[1]: Mounted /mnt/Harbormaster.
Mar 27 22:00:01 Harbormaster systemd[1]: proc-sys-fs-binfmt_misc.automount: Got automount request for /proc/sys/fs/binfmt_misc, triggered by 6305 (pydf)
Mar 27 22:00:01 Harbormaster systemd[1]: Mounting Arbitrary Executable File Formats File System...
Mar 27 22:00:01 Harbormaster systemd[1]: Mounted Arbitrary Executable File Formats File System.
Mar 27 22:00:01 Harbormaster kernel: [  223.523760] EXT4-fs (sdb2): mounted filesystem with ordered data mode. Quota mode: none.
Mar 27 22:05:32 Harbormaster rwhod[1040]: sending on interface eth0
Mar 27 22:05:54 Harbormaster pulseway: Failed to collect BiosData for assets report
Mar 27 22:07:55 Harbormaster watchdog[2566]: device eth0 did not receive anything since last check
Mar 27 22:08:01 Harbormaster watchdog[2566]: message repeated 6 times: [ device eth0 did not receive anything since last check]
Mar 27 22:08:02 Harbormaster watchdog[2566]: device eth0 did not receive anything since last check
Mar 27 22:08:03 Harbormaster watchdog[2566]: device eth0 did not receive anything since last check
Mar 27 22:08:06 Harbormaster watchdog[2566]: message repeated 3 times: [ device eth0 did not receive anything since last check]
Mar 27 22:08:06 Harbormaster systemd[2206]: tmp-raspiBackup.mount: Succeeded.
Mar 27 22:08:06 Harbormaster systemd[4062]: tmp-raspiBackup.mount: Succeeded.
Mar 27 22:08:06 Harbormaster systemd[1]: tmp-raspiBackup.mount: Succeeded.
Mar 27 22:08:07 Harbormaster watchdog[2566]: device eth0 did not receive anything since last check
Mar 27 22:08:19 Harbormaster watchdog[2566]: message repeated 12 times: [ device eth0 did not receive anything since last check]
Mar 27 22:08:20 Harbormaster watchdog[2566]: device eth0 did not receive anything since last check
Mar 27 22:08:32 Harbormaster watchdog[2566]: message repeated 12 times: [ device eth0 did not receive anything since last check]
Mar 27 22:08:32 Harbormaster rwhod[1040]: sending on interface eth0
Mar 27 22:08:33 Harbormaster watchdog[2566]: device eth0 did not receive anything since last check
Mar 27 22:08:36 Harbormaster kernel: [  738.217710] EXT4-fs (sdb2): unmounting filesystem.
Mar 27 22:08:36 Harbormaster kernel: [  738.649603] EXT4-fs (sdb2): mounted filesystem with ordered data mode. Quota mode: none.
Mar 27 22:08:36 Harbormaster watchdog[2566]: message repeated 3 times: [ device eth0 did not receive anything since last check]
Mar 27 22:08:37 Harbormaster systemd[4062]: tmp-raspiBackup.mount: Succeeded.
Mar 27 22:08:37 Harbormaster systemd[1]: tmp-raspiBackup.mount: Succeeded.
Mar 27 22:08:37 Harbormaster systemd[2206]: tmp-raspiBackup.mount: Succeeded.
Mar 27 22:08:37 Harbormaster kernel: [  739.001768] EXT4-fs (sdb2): unmounting filesystem.
Mar 27 22:08:37 Harbormaster watchdog[2566]: device eth0 did not receive anything since last check
Mar 27 22:08:37 Harbormaster kernel: [  739.573317] FAT-fs (sdb1): Volume was not properly unmounted. Some data may be corrupt. Please run fsck.
Mar 27 22:08:37 Harbormaster kernel: [  739.806237] EXT4-fs (sdb2): mounted filesystem with ordered data mode. Quota mode: none.
Mar 27 22:08:38 Harbormaster systemd[4062]: tmp-boot.mount: Succeeded.
Mar 27 22:08:38 Harbormaster systemd[2206]: tmp-boot.mount: Succeeded.
Mar 27 22:08:38 Harbormaster systemd[1]: tmp-boot.mount: Succeeded.
Mar 27 22:08:38 Harbormaster systemd[2206]: tmp-root.mount: Succeeded.
Mar 27 22:08:38 Harbormaster systemd[4062]: tmp-root.mount: Succeeded.
Mar 27 22:08:38 Harbormaster systemd[1]: tmp-root.mount: Succeeded.
Mar 27 22:08:38 Harbormaster kernel: [  740.149361] EXT4-fs (sdb2): unmounting filesystem.
Mar 27 22:08:38 Harbormaster watchdog[2566]: device eth0 did not receive anything since last check
Mar 27 22:08:38 Harbormaster raspiBackup: Stopped 0.6.8 (4b9c22a). rc 0
Mar 27 22:08:39 Harbormaster watchdog[2566]: device eth0 did not receive anything since last check
Mar 27 22:08:40 Harbormaster watchdog[2566]: device eth0 did not receive anything since last check
Mar 27 22:08:41 Harbormaster watchdog[2566]: device eth0 did not receive anything since last check
Mar 27 22:08:49 Harbormaster watchdog[2566]: message repeated 8 times: [ device eth0 did not receive anything since last check]
framps commented 1 year ago

I bet the unmounting is causing this

raspiBackup does some mounts and umounts of the partitions the backup is restored to. But there is no mounting or umounting done on the backup partition - at least when you don't use the dynamic_mount option and it's not used by you. Looks like systemd does this mount/umount on your system. You can scan the debug log for any mounts/umounts executed by raspiBackup :wink:

I just setup a buster with watchdog (thx you provided the config info and I was able to setup everything quickly) and create a rsync backup on the nfs storage on my Synology DS418Play. Let's see whether I can reproduce your issue ...

framps commented 1 year ago

No reboot triggered by watchdog. Restore syslog:

Mar 28 20:37:08 buster-lite-watchdog raspiBackup.sh: Started 0.6.8 (e2037d2)
Mar 28 20:38:20 buster-lite-watchdog systemd[1]: Starting Cleanup of Temporary Directories...
Mar 28 20:38:21 buster-lite-watchdog systemd[1]: systemd-tmpfiles-clean.service: Succeeded.
Mar 28 20:38:21 buster-lite-watchdog systemd[1]: Started Cleanup of Temporary Directories.
Mar 28 20:39:12 buster-lite-watchdog kernel: [  986.058210] usb 1-1.4: new high-speed USB device number 4 using dwc_otg
Mar 28 20:39:12 buster-lite-watchdog kernel: [  986.193096] usb 1-1.4: New USB device found, idVendor=05e3, idProduct=0749, bcdDevice=15.35
Mar 28 20:39:12 buster-lite-watchdog kernel: [  986.193132] usb 1-1.4: New USB device strings: Mfr=3, Product=4, SerialNumber=5
Mar 28 20:39:12 buster-lite-watchdog kernel: [  986.193148] usb 1-1.4: Product: USB3.0 Card Reader
Mar 28 20:39:12 buster-lite-watchdog kernel: [  986.193163] usb 1-1.4: Manufacturer: Generic
Mar 28 20:39:12 buster-lite-watchdog kernel: [  986.193178] usb 1-1.4: SerialNumber: 000000001536
Mar 28 20:39:12 buster-lite-watchdog kernel: [  986.194329] usb-storage 1-1.4:1.0: USB Mass Storage device detected
Mar 28 20:39:12 buster-lite-watchdog kernel: [  986.206855] scsi host0: usb-storage 1-1.4:1.0
Mar 28 20:39:12 buster-lite-watchdog mtp-probe: checking bus 1, device 4: "/sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.4"
Mar 28 20:39:12 buster-lite-watchdog mtp-probe: bus: 1, device: 4 was not an MTP device
Mar 28 20:39:12 buster-lite-watchdog kernel: [  986.316721] usbcore: registered new interface driver uas
Mar 28 20:39:12 buster-lite-watchdog mtp-probe: checking bus 1, device 4: "/sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.4"
Mar 28 20:39:12 buster-lite-watchdog mtp-probe: bus: 1, device: 4 was not an MTP device
Mar 28 20:39:13 buster-lite-watchdog kernel: [  987.280115] scsi 0:0:0:0: Direct-Access     Generic  MassStorageClass 1536 PQ: 0 ANSI: 6
Mar 28 20:39:13 buster-lite-watchdog kernel: [  987.297620] sd 0:0:0:0: Attached scsi generic sg0 type 0
Mar 28 20:39:13 buster-lite-watchdog kernel: [  987.612353] sd 0:0:0:0: [sda] 31422464 512-byte logical blocks: (16.1 GB/15.0 GiB)
Mar 28 20:39:13 buster-lite-watchdog kernel: [  987.613376] sd 0:0:0:0: [sda] Write Protect is off
Mar 28 20:39:13 buster-lite-watchdog kernel: [  987.613396] sd 0:0:0:0: [sda] Mode Sense: 21 00 00 00
Mar 28 20:39:13 buster-lite-watchdog kernel: [  987.614315] sd 0:0:0:0: [sda] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA
Mar 28 20:39:13 buster-lite-watchdog kernel: [  987.654032]  sda: sda1 sda2
Mar 28 20:39:13 buster-lite-watchdog kernel: [  987.658536] sd 0:0:0:0: [sda] Attached SCSI removable disk
Mar 28 20:40:04 buster-lite-watchdog raspiBackup.sh: Started 0.6.8 (e2037d2)
Mar 28 20:40:08 buster-lite-watchdog raspiBackup: Stopped 0.6.8 (e2037d2). rc 108
Mar 28 20:40:17 buster-lite-watchdog raspiBackup.sh: Started 0.6.8 (e2037d2)
Mar 28 20:40:27 buster-lite-watchdog kernel: [ 1061.223768]  sda: sda1 sda2
Mar 28 20:40:27 buster-lite-watchdog kernel: [ 1061.708994]  sda: sda1 sda2
Mar 28 20:40:27 buster-lite-watchdog kernel: [ 1061.716914]  sda: sda1 sda2
Mar 28 20:40:30 buster-lite-watchdog systemd[1]: Started Session 4 of user pi.
Mar 28 20:40:31 buster-lite-watchdog kernel: [ 1065.706968]  sda: sda1 sda2
Mar 28 20:41:15 buster-lite-watchdog kernel: [ 1109.145362]  sda: sda1 sda2
Mar 28 20:41:18 buster-lite-watchdog kernel: [ 1112.951549] EXT4-fs (sda2): mounted filesystem with ordered data mode. Opts: (null)
Mar 28 20:45:57 buster-lite-watchdog systemd[1]: tmp-raspiBackup.mount: Succeeded.
Mar 28 20:45:57 buster-lite-watchdog systemd[546]: tmp-raspiBackup.mount: Succeeded.
Mar 28 20:46:00 buster-lite-watchdog kernel: [ 1394.989672] EXT4-fs (sda2): mounted filesystem with ordered data mode. Opts: (null)
Mar 28 20:46:01 buster-lite-watchdog systemd[546]: tmp-raspiBackup.mount: Succeeded.
Mar 28 20:46:01 buster-lite-watchdog systemd[1]: tmp-raspiBackup.mount: Succeeded.
Mar 28 20:46:03 buster-lite-watchdog kernel: [ 1397.141144] EXT4-fs (sda2): mounted filesystem with ordered data mode. Opts: (null)
Mar 28 20:46:03 buster-lite-watchdog systemd[546]: tmp-boot.mount: Succeeded.
Mar 28 20:46:03 buster-lite-watchdog systemd[1]: tmp-boot.mount: Succeeded.
Mar 28 20:46:03 buster-lite-watchdog systemd[1]: tmp-root.mount: Succeeded.
Mar 28 20:46:03 buster-lite-watchdog systemd[546]: tmp-root.mount: Succeeded.
Mar 28 20:46:04 buster-lite-watchdog raspiBackup: Stopped 0.6.8 (e2037d2). rc 0

There is one major difference between your any my setup: I use nfs on a Synology running Linux - you use CIFS running on Windows. Did you check the Windows logs for CIFS error messages ?

p1r473 commented 1 year ago

Thanks for checking! Its definitely triggered by raspiBackup but I guess not a direct raspiBackup issue. Oh well. At least it doesnt happen on a backup. only a restore

No CIFS errors 🤷‍♂️

framps commented 1 year ago

No CIFS errors

Then it's some config/setup on your Raspberry. I noticed you use systemd automount. I got some issues with automounts and finally added checks whether automount is enabled and reject a restore. systemd automounts is not checked for. Just a guess ... maybe disable systemd automount on your Raspberry and try again a restore ... Actually I'm just guessing.

p1r473 commented 1 year ago

Heres my mounts:

//BLACKPEARL/Monkeebutt /mnt/Monkeebutt cifs _netdev,nofail,noauto,x-systemd.automount,x-systemd.after=network-online.target,x-systemd.mount-timeout=infinity,credentials=[TOP-SECRET],vers=3.1.1 0 0

I got rid of x-systemd.automount, manually mounted, and same issue

Oh well, I will just need to live with reboots after restores, or turn off Watchdog before I restore I guess. I dont do restores often, would be worse if it happened on backups which I do nightly Ill keep digging as time permits

framps commented 1 year ago

Oh well, I will just need to live with reboots after restores, or turn off Watchdog before I restore I guess

On all my webpages and videos I suggest to prepare a SD card with plain RaspbianOS and pull this off the shelf when you have to restore a backup. I'm sure this will work for you :wink:

p1r473 commented 1 year ago

I noticed you use systemd automount

How do you do it? I just did what I found on google 😅

p1r473 commented 1 year ago

Oh well, I will just need to live with reboots after restores, or turn off Watchdog before I restore I guess

On all my webpages and videos I suggest to prepare a SD card with plain RaspbianOS and pull this off the shelf when you have to restore a backup. I'm sure this will work for you 😉

Yea I mean its not a huge issue, but annoying!

framps commented 1 year ago

How do you do it? I just did what I found on google

I don't use automount :smile:

Yea I mean its not a huge issue, but annoying!

I agree. Why don't you setup a dedicated Raspberry as a backupserver which exposes backup space via nfs? That way you can create incremental backups with rsync and will not face this ugly restore issue :wink:

framps commented 1 year ago

Thank you very much for your donation :+1:

p1r473 commented 1 year ago

Thank you very much for your help👍

p1r473 commented 1 year ago

Let me know if you have any other ideas :)

framps commented 1 year ago

I unfortunately don't have any idea :cry:

I have and have had issues with automount. I noticed you have a lot of mount messages in your backup log. I don't have them when I tried to recreate your issue. I would try to disable automount if possible.

Other than that you may switch to nfs instead of cifs and will be able to create incremental backups which you cannot with tar.

Anyhow there fortunately is a workaround available: Just create a plain RaspbianOS SD card which you use to restore a backup. That way you don't have alls the additional configuration and services active which may cause the issue :wink: