First off, wonderful plugin! It’s these third party plugins that take the Vera and make it an amazing tool; DataMine especially so! I’ve been using DM for a couple months, had 34 channels logging, adding more every week, and loved it… until now. I have to say this looks like the Vera’s (and a bit my) fault, but I now have no faith in this setup for data collection and archiving until I understand how to fix or avoid this problem.
Here’s my situation: I was working on my insteon network links using the PC based HomeLinc software, and unplugged my Insteon modem from the powered 4 port USB 1.1 hub where I have it plugged in. I have the following devices in the USB hub that is connected to my vera lite:
USB to Serial adapter (for power monitor interface)
4GB USB flash drive (Datamine)
1GB USB flash drive (Vera Logs)
Insteon PowerLineModem (not running altsteon, yet)
I think that unplugging must have caused a USB bus reset or something; as then I noticed in the status messages for the Vera’s USB logging (which is enabled) that it couldn’t find it’s logging drive… and it mentioned something about formatting… but I only saw activity on the dedicated log USB stick, so I thought no big deal.
I shut everything down after I finished my linking work and plugged everything back in: After a reboot, DataMine showed 0 channels. It looks like the Vera grabbed the USB stick I had DataMine running on.
The DM diagnostics output is below:
-1-===========================================================================
09 08/09/13 0:18:45.647 JobHandler_LuaUPnP::Run device 152 dataMine graphing and logging room 0 type urn:schemas-cd-jackson-com:device:DataMine:1 id parent 0/0xcda358 upnp: 0 <0x2b077000>
50 08/09/13 0:18:48.352 luup_log:152: dataMine: Initialising dataMine System (0.980) LEAK this:208896 start:208896 to 0x10d9000 <0x2b9ab680>
06 08/09/13 0:18:48.353 Device_Variable::m_szValue_set device: 152 service: urn:cd-jackson-com:serviceId:DataMine1 variable: e[35;1merrorStatuse[0m was: false now: false #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1 <0x2b9ab680>
06 08/09/13 0:18:48.353 Device_Variable::m_szValue_set device: 152 service: urn:cd-jackson-com:serviceId:DataMine1 variable: e[35;1mChannelCnte[0m was: 0 now: 0 #hooks: 0 upnp: 0 v:0xdbcfb8/NONE duplicate:1 <0x2b9ab680>
06 08/09/13 0:18:48.374 Device_Variable::m_szValue_set device: 152 service: urn:cd-jackson-com:serviceId:DataMine1 variable: e[35;1mChannelRece[0m was: 0 now: 0 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1 <0x2b9ab680>
50 08/09/13 0:18:48.375 luup_log:152: dataMine: Mounting to UUID ‘283A-22C1’ <0x2b9ab680>
50 08/09/13 0:18:52.737 luup_log:152: dataMine: Error reading tmpfile during UUID check <0x2b9ab680>
50 08/09/13 0:18:53.168 luup_log:152: dataMine: No UUID mount ‘283A-22C1’ was found! <0x2b9ab680>
50 08/09/13 0:18:53.220 luup_log:152: dataMine: Error reading tmpfile during mountcheck <0x2b9ab680>
[…]
50 08/09/13 0:21:21.316 luup_log:152: dataMine: Initialising dataMine System (0.980) <0x2b9a7680>
06 08/09/13 0:21:21.317 Device_Variable::m_szValue_set device: 152 service: urn:cd-jackson-com:serviceId:DataMine1 variable: e[35;1merrorStatuse[0m was: false now: false #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1 <0x2b9a7680>
06 08/09/13 0:21:21.317 Device_Variable::m_szValue_set device: 152 service: urn:cd-jackson-com:serviceId:DataMine1 variable: e[35;1mChannelCnte[0m was: 0 now: 0 #hooks: 0 upnp: 0 v:0xb93778/NONE duplicate:1 <0x2b9a7680>
06 08/09/13 0:21:21.318 Device_Variable::m_szValue_set device: 152 service: urn:cd-jackson-com:serviceId:DataMine1 variable: e[35;1mChannelRece[0m was: 0 now: 0 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1 <0x2b9a7680>
50 08/09/13 0:21:21.318 luup_log:152: dataMine: Mounting to UUID ‘283A-22C1’ <0x2b9a7680>
50 08/09/13 0:21:22.670 luup_log:152: dataMine: Error reading tmpfile during UUID check <0x2b9a7680>
50 08/09/13 0:21:22.688 luup_log:152: dataMine: No UUID mount ‘283A-22C1’ was found! <0x2b9a7680>
50 08/09/13 0:21:22.714 luup_log:152: dataMine: Error reading tmpfile during mountcheck <0x2b9a7680>
06 08/09/13 0:21:22.714 Device_Variable::m_szValue_set device: 152 service: urn:cd-jackson-com:serviceId:DataMine1 variable: e[35;1mmountLocatione[0m was: now: #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1 <0x2b9a7680>
06 08/09/13 0:21:22.715 Device_Variable::m_szValue_set device: 152 service: urn:cd-jackson-com:serviceId:DataMine1 variable: e[35;1mmountTypee[0m was: now: #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1 <0x2b9a7680>
06 08/09/13 0:21:22.797 Device_Variable::m_szValue_set device: 152 service: urn:cd-jackson-com:serviceId:DataMine1 variable: e[35;1mChannelCnte[0m was: 0 now: 0 #hooks: 0 upnp: 0 v:0xb93778/NONE duplicate:1 <0x2b9a7680>
06 08/09/13 0:21:22.798 Device_Variable::m_szValue_set device: 152 service: urn:cd-jackson-com:serviceId:DataMine1 variable: e[35;1mChannelRece[0m was: 0 now: 0 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1 <0x2b9a7680>
50 08/09/13 0:21:22.799 luup_log:152: dataMine: Startup complete <0x2b9a7680>
50 08/09/13 0:21:37.310 luup_log:152: dataMine: Delete backups complete - No files found LEAK this:73728 start:102400 to 0xea6000 <0x2cda7680>
06 08/09/13 0:21:37.352 Device_Variable::m_szValue_set device: 152 service: urn:cd-jackson-com:serviceId:DataMine1 variable: e[35;1mdiskTotale[0m was: 11264 now: 11264 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1 LEAK this:73728 start:176128 to 0xeb8000 <0x2cda7680>
06 08/09/13 0:21:37.352 Device_Variable::m_szValue_set device: 152 service: urn:cd-jackson-com:serviceId:DataMine1 variable: e[35;1mdiskUsede[0m was: 2432 now: 2432 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1 <0x2cda7680>
06 08/09/13 0:21:37.352 Device_Variable::m_szValue_set device: 152 service: urn:cd-jackson-com:serviceId:DataMine1 variable: e[35;1mdiskFreee[0m was: 8832 now: 8832 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1 <0x2cda7680>
06 08/09/13 0:21:37.353 Device_Variable::m_szValue_set device: 152 service: urn:cd-jackson-com:serviceId:DataMine1 variable: e[35;1mdiskUsedPcnte[0m was: 22 now: 22 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1 <0x2cda7680>
-2-===========================================================================
/dev/sdb1: LABEL=“MiOS” UUID=“a33f7a02-0db2-44d4-a230-1010f2d9e056”
/dev/sda1: LABEL=“MiOS” UUID=“b31bd560-cdd4-4826-a563-d57817559b77”
-3-===========================================================================
rootfs on / type rootfs (rw)
/dev/root on /rom type squashfs (ro,relatime)
proc on /proc type proc (rw,noatime)
sysfs on /sys type sysfs (rw,noatime)
tmpfs on /tmp type tmpfs (rw,nosuid,nodev,noatime)
tmpfs on /dev type tmpfs (rw,noatime,size=512k,mode=755)
devpts on /dev/pts type devpts (rw,noatime,mode=600)
/dev/mtdblock7 on /overlay type jffs2 (rw,noatime)
overlayfs:/overlay on / type overlayfs (rw,noatime,lowerdir=/,upperdir=/overlay)
debugfs on /sys/kernel/debug type debugfs (rw,relatime)
/dev/sda1 on /tmp/log/cmh type ext3 (rw,noatime,nodiratime,errors=continue,barrier=0,data=ordered)
/dev/mtdblock8 on /mios type squashfs (ro,relatime)
none on /proc/bus/usb type usbfs (rw,relatime)
-4-===========================================================================
Disk /dev/mtdblock0: 0 MB, 524288 bytes
255 heads, 63 sectors/track, 0 cylinders
Units = cylinders of 16065 * 512 = 8225280 bytes
Disk /dev/mtdblock0 doesn’t contain a valid partition table
Disk /dev/sda: 999 MB, 999555072 bytes
31 heads, 62 sectors/track, 1015 cylinders
Units = cylinders of 1922 * 512 = 984064 bytes
Device Boot Start End Blocks Id System
/dev/sda1 * 1 546 524705+ 83 Linux
/dev/sda2 547 1015 450709 83 Linux
Disk /dev/sdb: 4039 MB, 4039114752 bytes
21 heads, 13 sectors/track, 28897 cylinders
Units = cylinders of 273 * 512 = 139776 bytes
Device Boot Start End Blocks Id System
/dev/sdb1 4 28898 3943932 b Win95 FAT32
-5-===========================================================================
SetDataDirectory-/dataMine/
SetMountUUID -283A-22C1
SetMountPoint -
SetManualMount -0
-6-===========================================================================
{“Version”:“0.980”,“dbVersion”:2,“Events”:{“count”:838,“last”:1352526163},“guiConfig”:[],“Variables”:[],“Graphs”:[],“LastWrite”:1375984223,“nextId”:1}
-7-===========================================================================
The GUID of the DataMine disk had changed to a33f7a02-0db2-44d4-a230-1010f2d9e056 and the label changed from DATAMINE to MiOS… ruh-roh. I took the DataMine USB stick out of the Vera, and put it in my Windows PC: windows wanted to format it. I pulled the stick, and put it back in the vera, and changed the GUID in the DM advanced config to match the new ID for the datamine disk. Dm started, with this debug:
-1-===========================================================================
09 08/09/13 10:42:26.822 JobHandler_LuaUPnP::Run device 152 dataMine graphing and logging room 0 type urn:schemas-cd-jackson-com:device:DataMine:1 id parent 0/0xf6e260 upnp: 0 <0x2b2c2000>
09 08/09/13 10:42:45.562 JobHandler_LuaUPnP::Run device 152 dataMine graphing and logging room 0 type urn:schemas-cd-jackson-com:device:DataMine:1 id parent 0/0xe6b638 upnp: 0 <0x2b583000>
50 08/09/13 10:42:50.281 luup_log:152: dataMine: Initialising dataMine System (0.980) <0x2bcb7680>
06 08/09/13 10:42:50.282 Device_Variable::m_szValue_set device: 152 service: urn:cd-jackson-com:serviceId:DataMine1 variable: e[35;1merrorStatuse[0m was: false now: false #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1 <0x2bcb7680>
06 08/09/13 10:42:50.283 Device_Variable::m_szValue_set device: 152 service: urn:cd-jackson-com:serviceId:DataMine1 variable: e[35;1mChannelCnte[0m was: 0 now: 0 #hooks: 0 upnp: 0 v:0xf4f240/NONE duplicate:1 <0x2bcb7680>
06 08/09/13 10:42:50.283 Device_Variable::m_szValue_set device: 152 service: urn:cd-jackson-com:serviceId:DataMine1 variable: e[35;1mChannelRece[0m was: 0 now: 0 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1 <0x2bcb7680>
50 08/09/13 10:42:50.283 luup_log:152: dataMine: Mounting to UUID ‘a33f7a02-0db2-44d4-a230-1010f2d9e056’ <0x2bcb7680>
50 08/09/13 10:42:51.928 luup_log:152: dataMine: UUID = /dev/sdb1: LABEL=“MiOS” UUID=“a33f7a02-0db2-44d4-a230-1010f2d9e056” <0x2bcb7680>
50 08/09/13 10:42:51.944 luup_log:152: dataMine: Found UUID ‘a33f7a02-0db2-44d4-a230-1010f2d9e056’ at ‘/dev/sdb1’ <0x2bcb7680>
50 08/09/13 10:42:51.968 luup_log:152: dataMine: Error reading tmpfile during mountcheck <0x2bcb7680>
06 08/09/13 10:42:51.969 Device_Variable::m_szValue_set device: 152 service: urn:cd-jackson-com:serviceId:DataMine1 variable: e[35;1mmountLocatione[0m was: now: #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1 <0x2bcb7680>
06 08/09/13 10:42:51.969 Device_Variable::m_szValue_set device: 152 service: urn:cd-jackson-com:serviceId:DataMine1 variable: e[35;1mmountTypee[0m was: now: #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1 <0x2bcb7680>
50 08/09/13 10:42:51.986 luup_log:152: dataMine: Mounting dataMine storage (/dev/sdb1) to (/dataMine/) <0x2bcb7680>
50 08/09/13 10:45:19.232 luup_log:152: dataMine: Mounted: /dev/sdb1 on /dataMine type ext4 (rw,relatime,barrier=1,data=ordered) <0x2bcb7680>
06 08/09/13 10:45:19.233 Device_Variable::m_szValue_set device: 152 service: urn:cd-jackson-com:serviceId:DataMine1 variable: e[35;1mmountLocatione[0m was: now: /dev/sdb1 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2bcb7680>
06 08/09/13 10:45:19.468 Device_Variable::m_szValue_set device: 152 service: urn:cd-jackson-com:serviceId:DataMine1 variable: e[35;1mmountTypee[0m was: now: ext4 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2bcb7680>
50 08/09/13 10:45:19.874 luup_log:152: dataMine: ERROR: Unable to open config file for read :: /dataMine/dataMineConfig.json <0x2bcb7680>
50 08/09/13 10:45:19.900 luup_log:152: dataMine: Primary config file load failed. No backup file found! <0x2bcb7680>
06 08/09/13 10:45:19.901 Device_Variable::m_szValue_set device: 152 service: urn:cd-jackson-com:serviceId:DataMine1 variable: e[35;1mChannelCnte[0m was: 0 now: 0 #hooks: 0 upnp: 0 v:0xf4f240/NONE duplicate:1 <0x2bcb7680>
06 08/09/13 10:45:19.901 Device_Variable::m_szValue_set device: 152 service: urn:cd-jackson-com:serviceId:DataMine1 variable: e[35;1mChannelRece[0m was: 0 now: 0 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1 <0x2bcb7680>
50 08/09/13 10:45:19.902 luup_log:152: dataMine: Reinitialising configuration structure <0x2bcb7680>
50 08/09/13 10:45:19.903 luup_log:152: dataMine: Startup complete <0x2bcb7680>
50 08/09/13 10:45:54.385 luup_log:152: dataMine: Delete backups complete - No files found <0x2ceb7680>
06 08/09/13 10:45:54.404 Device_Variable::m_szValue_set device: 152 service: urn:cd-jackson-com:serviceId:DataMine1 variable: e[35;1mdiskTotale[0m was: 11264 now: 3881992 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2ceb7680>
06 08/09/13 10:45:54.405 Device_Variable::m_szValue_set device: 152 service: urn:cd-jackson-com:serviceId:DataMine1 variable: e[35;1mdiskUsede[0m was: 2432 now: 92044 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2ceb7680>
06 08/09/13 10:45:54.405 Device_Variable::m_szValue_set device: 152 service: urn:cd-jackson-com:serviceId:DataMine1 variable: e[35;1mdiskFreee[0m was: 8832 now: 3592752 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2ceb7680>
06 08/09/13 10:45:54.406 Device_Variable::m_szValue_set device: 152 service: urn:cd-jackson-com:serviceId:DataMine1 variable: e[35;1mdiskUsedPcnte[0m was: 22 now: 2 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2ceb7680>
06 08/09/13 10:46:09.818 Device_Variable::m_szValue_set device: 152 service: urn:cd-jackson-com:serviceId:DataMine1 variable: e[35;1mChannelCnte[0m was: 0 now: 0 #hooks: 0 upnp: 0 v:0xf4f240/NONE duplicate:1 <0x2ceb7680>
06 08/09/13 10:46:09.818 Device_Variable::m_szValue_set device: 152 service: urn:cd-jackson-com:serviceId:DataMine1 variable: e[35;1mChannelRece[0m was: 0 now: 0 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1 <0x2ceb7680>
06 08/09/13 10:46:20.616 Device_Variable::m_szValue_set device: 152 service: urn:cd-jackson-com:serviceId:DataMine1 variable: e[35;1mChannelCnte[0m was: 0 now: 0 #hooks: 0 upnp: 0 v:0xf4f240/NONE duplicate:1 <0x2ceb7680>
06 08/09/13 10:46:20.616 Device_Variable::m_szValue_set device: 152 service: urn:cd-jackson-com:serviceId:DataMine1 variable: e[35;1mChannelRece[0m was: 0 now: 0 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1
-2-===========================================================================
/dev/sdb1: LABEL=“MiOS” UUID=“a33f7a02-0db2-44d4-a230-1010f2d9e056”
/dev/sda1: LABEL=“MiOS” UUID=“b31bd560-cdd4-4826-a563-d57817559b77”
-3-===========================================================================
rootfs on / type rootfs (rw)
/dev/root on /rom type squashfs (ro,relatime)
proc on /proc type proc (rw,noatime)
sysfs on /sys type sysfs (rw,noatime)
tmpfs on /tmp type tmpfs (rw,nosuid,nodev,noatime)
tmpfs on /dev type tmpfs (rw,noatime,size=512k,mode=755)
devpts on /dev/pts type devpts (rw,noatime,mode=600)
/dev/mtdblock7 on /overlay type jffs2 (rw,noatime)
overlayfs:/overlay on / type overlayfs (rw,noatime,lowerdir=/,upperdir=/overlay)
debugfs on /sys/kernel/debug type debugfs (rw,relatime)
/dev/sda1 on /tmp/log/cmh type ext3 (rw,noatime,nodiratime,errors=continue,barrier=0,data=ordered)
/dev/mtdblock8 on /mios type squashfs (ro,relatime)
none on /proc/bus/usb type usbfs (rw,relatime)
/dev/sdb1 on /dataMine type ext4 (rw,relatime,barrier=1,data=ordered)
-4-===========================================================================
Disk /dev/mtdblock0: 0 MB, 524288 bytes
255 heads, 63 sectors/track, 0 cylinders
Units = cylinders of 16065 * 512 = 8225280 bytes
Disk /dev/mtdblock0 doesn’t contain a valid partition table
Disk /dev/sda: 999 MB, 999555072 bytes
31 heads, 62 sectors/track, 1015 cylinders
Units = cylinders of 1922 * 512 = 984064 bytes
Device Boot Start End Blocks Id System
/dev/sda1 * 1 546 524705+ 83 Linux
/dev/sda2 547 1015 450709 83 Linux
Disk /dev/sdb: 4039 MB, 4039114752 bytes
21 heads, 13 sectors/track, 28897 cylinders
Units = cylinders of 273 * 512 = 139776 bytes
Device Boot Start End Blocks Id System
/dev/sdb1 4 28898 3943932 b Win95 FAT32
-5-===========================================================================
SetDataDirectory-/dataMine/
SetMountUUID -a33f7a02-0db2-44d4-a230-1010f2d9e056
SetMountPoint -
SetManualMount -0
-6-===========================================================================
{“LastWrite”:1376063180,“dbVersion”:2,“Events”:{“count”:200,“last”:1352146899},“Version”:“0.980”,“Variables”:[],“Graphs”:[],“guiConfig”:[],“nextId”:1}
-7-===========================================================================
So, looks like everything is lost, now… I can see that the DM folders were re-created, here is the directory structure on that USB stick:
-rw-r–r-- 1 root root 2554 Aug 8 23:42 InternetOk.log
-rw-r–r-- 1 root root 19023537 Aug 9 00:16 LuaUPnP.log
-rw-r–r-- 1 root root 49237 Aug 8 23:52 NetworkMonitor.log
-rw-r–r-- 1 root root 573 Aug 9 10:46 Notifications [R2234].txt
-rw-r–r-- 1 root root 37313 Aug 9 10:46 Notifications [R2235].txt
-rw-r–r-- 1 root root 66060 Aug 9 10:47 Notifications [R2236].txt
-rw-r–r-- 1 root root 151 Aug 9 10:47 dataMineConfig.json
drwxr-xr-x 2 root root 4096 Aug 9 10:45 database
drwx------ 2 root root 16384 Aug 8 12:45 lost+found
-rw-r–r-- 1 root root 26 Aug 8 12:46 mount_tests
-rw-r–r-- 1 root root 56377 Aug 8 23:29 serproxy.log
-rw-r–r-- 1 root root 0 Aug 8 23:29 signal.flag.log
-rw-r–r-- 1 root root 399 Aug 8 23:29 signal.log
So for sure the vera used this disk for its local logging. Not much hope for recovery here, I’ll be formatting a new disk and setting this one aside just in case, though.
I guess my take-aways from this are:
-I setup the USB storage to take the flash memory write cycle load off my vera’s local storage… I was surprised as to how much that vera logging USB stick was written to… but now, I wouldn’t use vera logging with DM unless your USB is rock solid; and even then maybe just when I’m trying to debug something, since it looks like it will nuke any USB drive that it sees if there are problems with the MiOS
-I really, really wish I had my config. Any way to backup the DM configs to a spot on the Vera’s local storage, if when there are big problems like this? Might my config be sitting in a temp folder somewhere?
-I really wish I had my data. I think it would be a big deal to have a ‘download backup’ function built in… and probably much more practical to just script SCP from another system to grab all the DM database files… but an automated backup to another disk / system would be great!
Thanks again, and be careful with your DM data if you have Vera logging turned on, too. I’d like to hear any thoughts from anyone on how to avoid this (aside from disabling Vera logging), or on easy backup solutions. I could see anyone’s vera logging stick failing eventually, and then the Vera going hunting for a new drive to format…
