search

marcone / teslausb

A smart USB drive for Tesla Dashcam - extended storage, auto archive, web viewer
MIT License
1.94k stars 355 forks source link

Backups not happening #82

Closed cribbstechnologies closed 5 years ago

cribbstechnologies commented 5 years ago

I seem to be having troubles with the Pi backing things up. I can shell into the Pi and mount the cam folder and look at the files and there are quite a few there.

On my CIFS share there's only one folder created and it's from several days ago and only includes some 0-second MP4s.

The date in my archiveloop.log matches what's in the fake HW clock but it's WAY off from what the actual date is.

dmesg output shows [ 43.566754] CIFS VFS: cifs_mount failed w/return code = -101 but if I switch to the CIFS mount and touch a file it shows up on my NAS.

Recent archiveloop.log output:

fsck from util-linux 2.29.2
fsck.fat 4.1 (2017-01-24)
0x41: Dirty bit is set. Fs was not properly unmounted and some data may be corrupt.
 Automatically removing dirty bit.
Performing changes.
/dev/loop0: 187 files, 16019/3785199 clusters
Thu  3 Nov 19:18:14 GMT 2016: Finished fsck on /mnt/cam.
Thu  3 Nov 19:18:14 GMT 2016: Moving clips to archive...
Thu  3 Nov 19:18:14 GMT 2016: Creating output directory ''
Thu  3 Nov 19:18:14 GMT 2016: Creating output directory ''
Thu  3 Nov 19:18:14 GMT 2016: Moved 0 file(s), failed to copy 0, deleted 0.
Thu  3 Nov 19:18:14 GMT 2016: Finished moving clips to archive.
Thu  3 Nov 19:18:14 GMT 2016: Unmounting /mnt/cam...
Thu  3 Nov 19:18:15 GMT 2016: Unmounted /mnt/cam.
Thu  3 Nov 19:18:15 GMT 2016: Finished archiving.
Thu  3 Nov 19:18:15 GMT 2016: No music archive configured
Thu  3 Nov 19:18:15 GMT 2016: Connecting usb to host...
Thu  3 Nov 19:18:15 GMT 2016: Connected usb to host.
Thu  3 Nov 19:18:15 GMT 2016: Waiting for archive to be unreachable...
Thu  3 Nov 19:56:27 GMT 2016: Sleeping before retry...
Thu  3 Nov 19:56:28 GMT 2016: Retrying...
raushel commented 5 years ago

CIFS may not like the large delta in your time on your pi. Would fix time / ntp on your pi and see if that fixes it.

Can you open /mnt/archive?

marcone commented 5 years ago

When you say "... there are quite a few there", do you mean there are quite a few files under TeslaCam/SavedClips, or under TeslaCam/RecentClips?

Asking because teslausb only backs up TeslaCam/SavedClips (which are the files that you manually save by pressing the button on the screen, plus files that Sentry Mode has saved), and your log output seems to indicate it didn't find any files in TeslaCam/SavedClips to back up.

cribbstechnologies commented 5 years ago

@marcone And there's a fundamental misunderstanding on my part :)

I'll go save some after I drive around for a while and see if it works then (it should). I'll close this until that happens and I experience issues then.

marcone commented 5 years ago

I do plan to add an option to have it backup the "recent clips" too, but right now that's not very useful yet, since there's only going to be at most an hour of those.

rudybroersma commented 5 years ago

I have the same issue, and I'm using rsync:

My logs tell me:

Tue 18 Jun 07:40:11 CEST 2019: Waiting for archive to be unreachable...
Tue 18 Jun 08:29:41 CEST 2019: Sleeping before retry...
Tue 18 Jun 08:29:42 CEST 2019: Retrying...
Tue 18 Jun 08:29:42 CEST 2019: Sleeping before retry...
Tue 18 Jun 08:29:43 CEST 2019: Retrying...
Tue 18 Jun 08:29:43 CEST 2019: Sleeping before retry...
Tue 18 Jun 08:29:44 CEST 2019: Retrying...
Tue 18 Jun 08:29:44 CEST 2019: Sleeping before retry...
Tue 18 Jun 08:29:45 CEST 2019: Retrying...
Tue 18 Jun 08:29:45 CEST 2019: Sleeping before retry...
Tue 18 Jun 08:29:47 CEST 2019: Retrying...
Tue 18 Jun 08:29:47 CEST 2019: Sleeping before retry...
Tue 18 Jun 08:29:48 CEST 2019: Retrying...
Tue 18 Jun 08:29:48 CEST 2019: Sleeping before retry...
Tue 18 Jun 08:29:49 CEST 2019: Retrying...
Tue 18 Jun 08:29:49 CEST 2019: Sleeping before retry...
Tue 18 Jun 08:29:50 CEST 2019: Retrying...
Tue 18 Jun 08:29:50 CEST 2019: Sleeping before retry...
Tue 18 Jun 08:29:51 CEST 2019: Retrying...
Tue 18 Jun 08:29:51 CEST 2019: Sleeping before retry...
Tue 18 Jun 08:29:52 CEST 2019: Retrying...
Tue 18 Jun 08:29:52 CEST 2019: Attempts exhausted.
Tue 18 Jun 08:29:52 CEST 2019: Archive is unreachable.
Tue 18 Jun 08:29:52 CEST 2019: Waiting for archive to be reachable...
Tue 18 Jun 08:29:54 CEST 2019: Archive is reachable.
Tue 18 Jun 08:30:15 CEST 2019: Archiving...
Tue 18 Jun 08:30:15 CEST 2019: Disconnecting usb from host...
Tue 18 Jun 08:30:15 CEST 2019: Disconnected usb from host.
Tue 18 Jun 08:30:15 CEST 2019: Starting recording archiving...
Tue 18 Jun 08:30:15 CEST 2019: Ensuring cam file is mounted...
Tue 18 Jun 08:30:15 CEST 2019: Mounting /mnt/cam...
Tue 18 Jun 08:30:15 CEST 2019: Mounted /mnt/cam.
Tue 18 Jun 08:30:15 CEST 2019: Ensured cam file is mounted.
Tue 18 Jun 08:30:15 CEST 2019: Running fsck on /mnt/cam...
fsck from util-linux 2.29.2
fsck.fat 4.1 (2017-01-24)
0x41: Dirty bit is set. Fs was not properly unmounted and some data may be corrupt.
 Automatically removing dirty bit.
Performing changes.
/dev/loop0: 308 files, 328492/1708729 clusters
Tue 18 Jun 08:30:17 CEST 2019: Finished fsck on /mnt/cam.
Tue 18 Jun 08:30:17 CEST 2019: Archiving through rsync...
Tue 18 Jun 08:30:22 CEST 2019: No files to archive through rsync.
Tue 18 Jun 08:30:22 CEST 2019: Unmounting /mnt/cam...
Tue 18 Jun 08:30:23 CEST 2019: Unmounted /mnt/cam.
Tue 18 Jun 08:30:23 CEST 2019: Finished archiving.
Tue 18 Jun 08:30:23 CEST 2019: No music archive configured
Tue 18 Jun 08:30:23 CEST 2019: Connecting usb to host...
Tue 18 Jun 08:30:23 CEST 2019: Connected usb to host.
Tue 18 Jun 08:30:24 CEST 2019: Waiting for archive to be unreachable...

When I mount /mnt/cam and look into /mnt/cam/TeslaCam/SavedClips/ there are quite a few:

root@teslausb-sn226l:/mnt/cam/TeslaCam/SavedClips# ls -la
total 144
drwxrwxrwx 9 root root 16384 Jun 18 00:59 .
drwxrwxrwx 4 root root 16384 Jun 18 03:07 ..
drwxrwxrwx 2 root root 16384 Jun 16 15:39 2019-06-16_22-39-49
drwxrwxrwx 2 root root 16384 Jun 17 11:34 2019-06-17_18-34-32
drwxrwxrwx 2 root root 16384 Jun 17 11:50 2019-06-17_18-50-43
drwxrwxrwx 2 root root 16384 Jun 17 13:32 2019-06-17_20-32-27
drwxrwxrwx 2 root root 16384 Jun 17 13:38 2019-06-17_20-38-43
drwxrwxrwx 2 root root 16384 Jun 17 14:31 2019-06-17_21-31-21
drwxrwxrwx 2 root root 16384 Jun 18 00:59 2019-06-18_07-59-44
root@teslausb-sn226l:/mnt/cam/TeslaCam/SavedClips# find . | wc -l
194
root@teslausb-sn226l:/mnt/cam/TeslaCam/SavedClips#

What I find strange are these lines: Tue 18 Jun 08:30:17 CEST 2019: Archiving through rsync... Tue 18 Jun 08:30:22 CEST 2019: No files to archive through rsync.

What I also noticed is this, when I manually tried running the rsync command:

root@teslausb-sn226l:~/bin# rsync -auvh --remove-source-files --no-perms --stats --log-file=/tmp/archive-rsync-cmd.log /mnt/cam/TeslaCam/saved* /mnt/cam/TeslaCam/SavedClips/* teslacam@X:/mnt/teslacam/teslacam/ | awk '/files transferred/{print $NF}'     
The authenticity of host 'X (bogus.ip.here)' can't be established.
RSA key fingerprint is SHA256:l+9biotFPkk/iWeDdcJPHgFh5TAaPHKq9xLfHXDd6po.
Are you sure you want to continue connecting (yes/no)? yes
Failed to add the host to the list of known hosts (/root/.ssh/known_hosts).

It seems rsync will wait forever for user input (and probably fail when ran from a script) and never rsync. Shouldn't rsync be called with -e "ssh -o StrictHostKeyChecking=no" instead? Or accept the host key during tesla-usb-setup (when the filesystem is still writable).

I've now manually mounted the fs read-write and accepted the host key. I believe that might be my issue but will let u know.

petebocken commented 4 years ago

I may be having a similar issue, not sure. My wife just got home and I didn't see any clips backed up to my server. I ssh into the Pi and I see several SavedClips and SentryClips in /backingfiles.

Here is dmesg right when she pulled into the driveway:


[Fri Mar 20 14:43:05 2020] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[Fri Mar 20 14:43:05 2020] brcmfmac: power management disabled
[Fri Mar 20 14:43:07 2020] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[Fri Mar 20 14:43:15 2020] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[Fri Mar 20 14:43:15 2020] brcmfmac: power management disabled
[Fri Mar 20 14:43:16 2020] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[Fri Mar 20 14:43:25 2020] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[Fri Mar 20 14:43:25 2020] brcmfmac: power management disabled
[Fri Mar 20 14:43:27 2020] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[Fri Mar 20 14:43:35 2020] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[Fri Mar 20 14:43:35 2020] brcmfmac: power management disabled
[Fri Mar 20 14:43:37 2020] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[Fri Mar 20 14:43:49 2020] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[Fri Mar 20 14:43:49 2020] brcmfmac: power management disabled
[Fri Mar 20 14:43:50 2020] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[Fri Mar 20 14:43:58 2020] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[Fri Mar 20 14:43:58 2020] brcmfmac: power management disabled
[Fri Mar 20 14:43:59 2020] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[Fri Mar 20 14:44:07 2020] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[Fri Mar 20 14:44:07 2020] brcmfmac: power management disabled
[Fri Mar 20 14:44:08 2020] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[Fri Mar 20 14:44:18 2020]  loop2: p1
[Fri Mar 20 14:44:20 2020] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[Fri Mar 20 14:44:20 2020] brcmfmac: power management disabled
[Fri Mar 20 14:44:21 2020] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[Fri Mar 20 14:44:31 2020]  loop3: p1
[Fri Mar 20 14:44:33 2020]  loop3: p1
[Fri Mar 20 14:44:34 2020] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[Fri Mar 20 14:44:34 2020] brcmfmac: power management disabled
[Fri Mar 20 14:44:35 2020] No dialect specified on mount. Default has changed to a more secure dialect, SMB2.1 or later (e.g. SMB3), from CIFS (SMB1). To use the less secure SMB1 dialect to access old servers which do not support SMB3 (or SMB2.1) specify vers=1.0 on mount.
[Fri Mar 20 14:44:35 2020] CIFS VFS: Error connecting to socket. Aborting operation.
[Fri Mar 20 14:44:35 2020] CIFS VFS: cifs_mount failed w/return code = -101
[Fri Mar 20 14:44:36 2020] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[Fri Mar 20 14:44:36 2020] No dialect specified on mount. Default has changed to a more secure dialect, SMB2.1 or later (e.g. SMB3), from CIFS (SMB1). To use the less secure SMB1 dialect to access old servers which do not support SMB3 (or SMB2.1) specify vers=1.0 on mount.
[Fri Mar 20 14:44:36 2020] CIFS VFS: Error connecting to socket. Aborting operation.
[Fri Mar 20 14:44:36 2020] CIFS VFS: cifs_mount failed w/return code = -101
[Fri Mar 20 14:44:38 2020] No dialect specified on mount. Default has changed to a more secure dialect, SMB2.1 or later (e.g. SMB3), from CIFS (SMB1). To use the less secure SMB1 dialect to access old servers which do not support SMB3 (or SMB2.1) specify vers=1.0 on mount.
[Fri Mar 20 14:44:38 2020] CIFS VFS: Error connecting to socket. Aborting operation.
[Fri Mar 20 14:44:38 2020] CIFS VFS: cifs_mount failed w/return code = -101
[Fri Mar 20 14:44:39 2020] No dialect specified on mount. Default has changed to a more secure dialect, SMB2.1 or later (e.g. SMB3), from CIFS (SMB1). To use the less secure SMB1 dialect to access old servers which do not support SMB3 (or SMB2.1) specify vers=1.0 on mount.
[Fri Mar 20 14:44:39 2020] CIFS VFS: Error connecting to socket. Aborting operation.
[Fri Mar 20 14:44:39 2020] CIFS VFS: cifs_mount failed w/return code = -101
[Fri Mar 20 14:44:40 2020] No dialect specified on mount. Default has changed to a more secure dialect, SMB2.1 or later (e.g. SMB3), from CIFS (SMB1). To use the less secure SMB1 dialect to access old servers which do not support SMB3 (or SMB2.1) specify vers=1.0 on mount.
[Fri Mar 20 14:44:40 2020] CIFS VFS: Error connecting to socket. Aborting operation.
[Fri Mar 20 14:44:40 2020] CIFS VFS: cifs_mount failed w/return code = -101
[Fri Mar 20 14:44:41 2020] No dialect specified on mount. Default has changed to a more secure dialect, SMB2.1 or later (e.g. SMB3), from CIFS (SMB1). To use the less secure SMB1 dialect to access old servers which do not support SMB3 (or SMB2.1) specify vers=1.0 on mount.
[Fri Mar 20 14:44:41 2020] CIFS VFS: Error connecting to socket. Aborting operation.
[Fri Mar 20 14:44:41 2020] CIFS VFS: cifs_mount failed w/return code = -101
[Fri Mar 20 14:44:42 2020] No dialect specified on mount. Default has changed to a more secure dialect, SMB2.1 or later (e.g. SMB3), from CIFS (SMB1). To use the less secure SMB1 dialect to access old servers which do not support SMB3 (or SMB2.1) specify vers=1.0 on mount.
[Fri Mar 20 14:44:48 2020] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[Fri Mar 20 14:44:48 2020] brcmfmac: power management disabled
[Fri Mar 20 14:44:50 2020] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[Fri Mar 20 14:44:54 2020] Mass Storage Function, version: 2009/09/11
[Fri Mar 20 14:44:54 2020] LUN: removable file: (no medium)
[Fri Mar 20 14:44:54 2020] LUN: removable file: /backingfiles/music_disk.bin
[Fri Mar 20 14:44:54 2020] LUN: removable file: /backingfiles/cam_disk.bin
[Fri Mar 20 14:44:54 2020] Number of LUNs=2
[Fri Mar 20 14:44:54 2020] g_mass_storage gadget: Mass Storage Gadget, version: 2009/09/11
[Fri Mar 20 14:44:54 2020] g_mass_storage gadget: g_mass_storage ready
[Fri Mar 20 14:44:54 2020] dwc2 20980000.usb: bound driver g_mass_storage
[Fri Mar 20 14:44:54 2020] dwc2 20980000.usb: new device is high-speed
[Fri Mar 20 14:44:54 2020] dwc2 20980000.usb: new device is high-speed
[Fri Mar 20 14:44:54 2020] dwc2 20980000.usb: new address 25
[Fri Mar 20 14:44:54 2020] g_mass_storage gadget: high-speed config #1: Linux File-Backed Storage
[Fri Mar 20 14:44:59 2020] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[Fri Mar 20 14:44:59 2020] brcmfmac: power management disabled
[Fri Mar 20 14:45:00 2020] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[Fri Mar 20 14:45:07 2020] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[Fri Mar 20 14:45:07 2020] brcmfmac: power management disabled
[Fri Mar 20 14:45:08 2020] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[Fri Mar 20 14:45:16 2020] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[Fri Mar 20 14:45:16 2020] brcmfmac: power management disabled
[Fri Mar 20 14:45:18 2020] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[Fri Mar 20 15:27:53 2020]  loop3: p1
[Fri Mar 20 15:27:53 2020]  loop3: p1```
petebocken commented 4 years ago

I rebooted the Pi over SSH and it started backing up all the clips just fine. I'll continue watching and see if this behavior continues.

I may be having a similar issue, not sure. My wife just got home and I didn't see any clips backed up to my server. I ssh into the Pi and I see several SavedClips and SentryClips in /backingfiles.