dataMine graphing and logging[41] : Running Lua Startup stuck

dataMine graphing and logging[41] : Running Lua Startup

have this message - dataMine has been working flawlessly but since I added 6 extra channels (only have total 18 channels) it has started to play and stuck on this message.

for a few days, it would be like this and after 10 or so minutes restart.

now permanently stuck.

have rebooted a couple of times.

same thing.

HELP.

! :stuck_out_tongue:

cat /var/log/cmh/LuaUPnP.log | grep -i DataMine
09 04/30/13 23:30:41.902 JobHandler_LuaUPnP::Run device 41 dataMine graphing and logging room 0 type urn:schemas-cd-jackson-com:device:DataMine:1 id parent 0/0xb4ab40 upnp: 0 <0x2aebf000>
09 04/30/13 23:31:00.502 JobHandler_LuaUPnP::Run device 41 dataMine graphing and logging room 0 type urn:schemas-cd-jackson-com:device:DataMine:1 id parent 0/0x9dab48 upnp: 0 <0x2aba8000>
50 04/30/13 23:31:09.612 luup_log:41: dataMine: Initialising dataMine System (0.976) <0x2b2db680>
06 04/30/13 23:31:09.613 Device_Variable::m_szValue_set device: 41 service: urn:cd-jackson-com:serviceId:DataMine1 variable: ChannelCnt was: 0 now: 0 #hooks: 0 upnp: 0 v:0xa97468/NONE duplicate:1 <0x2b2db680>
06 04/30/13 23:31:09.613 Device_Variable::m_szValue_set device: 41 service: urn:cd-jackson-com:serviceId:DataMine1 variable: ChannelRec was: 0 now: 0 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1 <0x2b2db680>
50 04/30/13 23:31:09.613 luup_log:41: dataMine: Mounting to UUID ‘4660-03E4’ <0x2b2db680>
50 04/30/13 23:31:10.460 luup_log:41: dataMine: UUID = /dev/sda1: LABEL=“VERADISK” UUID=“4660-03E4” <0x2b2db680>
50 04/30/13 23:31:10.478 luup_log:41: dataMine: Found UUID ‘4660-03E4’ at ‘/dev/sda1’ <0x2b2db680>
50 04/30/13 23:31:10.513 luup_log:41: dataMine: Error reading tmpfile during mountcheck <0x2b2db680>
06 04/30/13 23:31:10.514 Device_Variable::m_szValue_set device: 41 service: urn:cd-jackson-com:serviceId:DataMine1 variable: mountLocation was: /dev/sda1 now: #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2b2db680>
06 04/30/13 23:31:10.515 Device_Variable::m_szValue_set device: 41 service: urn:cd-jackson-com:serviceId:DataMine1 variable: mountType was: vfat now: #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2b2db680>
50 04/30/13 23:31:10.553 luup_log:41: dataMine: Mounting dataMine storage (/dev/sda1) to (/dataMine/) <0x2b2db680>
50 04/30/13 23:31:12.228 luup_log:41: dataMine: Mounted: /dev/sda1 on /dataMine type vfat (rw,relatime,fmask=0022,dmask=0022,codepage=cp437,iocharset=iso8859-1,shortname=mixed,errors=remount-ro) <0x2b2db680>
06 04/30/13 23:31:12.229 Device_Variable::m_szValue_set device: 41 service: urn:cd-jackson-com:serviceId:DataMine1 variable: mountLocation was: now: /dev/sda1 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2b2db680>
06 04/30/13 23:31:12.230 Device_Variable::m_szValue_set device: 41 service: urn:cd-jackson-com:serviceId:DataMine1 variable: mountType was: now: vfat #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2b2db680>
50 04/30/13 23:31:12.333 luup_log:41: dataMine: ERROR: Config file was zero length <0x2b2db680>
50 04/30/13 23:31:14.525 luup_log:41: dataMine: Primary config file load failed. Resorting to backup ‘/dataMine/dataMineConfig.json.Tue Apr 30 23-07-24 2013.backup’ LEAK this:98304 start:946176 to 0xe79000 <0x2b2db680>
09 04/30/13 23:31:52.668 JobHandler_LuaUPnP::Run device 41 dataMine graphing and logging room 0 type urn:schemas-cd-jackson-com:device:DataMine:1 id parent 0/0xaf5b18 upnp: 0 <0x2b6dd000>
50 04/30/13 23:32:02.997 luup_log:41: dataMine: Initialising dataMine System (0.976) <0x2c011680>
06 04/30/13 23:32:02.998 Device_Variable::m_szValue_set device: 41 service: urn:cd-jackson-com:serviceId:DataMine1 variable: ChannelCnt was: 0 now: 0 #hooks: 0 upnp: 0 v:0xbb2400/NONE duplicate:1 <0x2c011680>
06 04/30/13 23:32:02.998 Device_Variable::m_szValue_set device: 41 service: urn:cd-jackson-com:serviceId:DataMine1 variable: ChannelRec was: 0 now: 0 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1 <0x2c011680>
50 04/30/13 23:32:02.999 luup_log:41: dataMine: Mounting to UUID ‘4660-03E4’ <0x2c011680>
50 04/30/13 23:32:04.610 luup_log:41: dataMine: UUID = /dev/sda1: LABEL=“VERADISK” UUID=“4660-03E4” <0x2c011680>
50 04/30/13 23:32:04.650 luup_log:41: dataMine: Found UUID ‘4660-03E4’ at ‘/dev/sda1’ <0x2c011680>
50 04/30/13 23:32:04.718 luup_log:41: dataMine: Mounted: /dev/sda1 on /dataMine type vfat (rw,relatime,fmask=0022,dmask=0022,codepage=cp437,iocharset=iso8859-1,shortname=mixed,errors=remount-ro) <0x2c011680>
06 04/30/13 23:32:04.718 Device_Variable::m_szValue_set device: 41 service: urn:cd-jackson-com:serviceId:DataMine1 variable: mountLocation was: /dev/sda1 now: /dev/sda1 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1 <0x2c011680>
06 04/30/13 23:32:04.719 Device_Variable::m_szValue_set device: 41 service: urn:cd-jackson-com:serviceId:DataMine1 variable: mountType was: vfat now: vfat #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1 <0x2c011680>
50 04/30/13 23:32:04.790 luup_log:41: dataMine: ERROR: Config file was zero length <0x2c011680>
50 04/30/13 23:32:05.620 luup_log:41: dataMine: Primary config file load failed. Resorting to backup ‘/dataMine/dataMineConfig.json.Tue Apr 30 23-07-24 2013.backup’ LEAK this:8192 start:839680 to 0xf7a000 <0x2c011680>

cat /var/log/cmh/LuaUPnP.log | grep -i DataMine
09 04/30/13 23:30:41.902 JobHandler_LuaUPnP::Run device 41 dataMine graphing and logging room 0 type urn:schemas-cd-jackson-com:device:DataMine:1 id parent 0/0xb4ab40 upnp: 0 <0x2aebf000>
09 04/30/13 23:31:00.502 JobHandler_LuaUPnP::Run device 41 dataMine graphing and logging room 0 type urn:schemas-cd-jackson-com:device:DataMine:1 id parent 0/0x9dab48 upnp: 0 <0x2aba8000>
50 04/30/13 23:31:09.612 luup_log:41: dataMine: Initialising dataMine System (0.976) <0x2b2db680>
06 04/30/13 23:31:09.613 Device_Variable::m_szValue_set device: 41 service: urn:cd-jackson-com:serviceId:DataMine1 variable: ChannelCnt was: 0 now: 0 #hooks: 0 upnp: 0 v:0xa97468/NONE duplicate:1 <0x2b2db680>
06 04/30/13 23:31:09.613 Device_Variable::m_szValue_set device: 41 service: urn:cd-jackson-com:serviceId:DataMine1 variable: ChannelRec was: 0 now: 0 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1 <0x2b2db680>
50 04/30/13 23:31:09.613 luup_log:41: dataMine: Mounting to UUID ‘4660-03E4’ <0x2b2db680>
50 04/30/13 23:31:10.460 luup_log:41: dataMine: UUID = /dev/sda1: LABEL=“VERADISK” UUID=“4660-03E4” <0x2b2db680>
50 04/30/13 23:31:10.478 luup_log:41: dataMine: Found UUID ‘4660-03E4’ at ‘/dev/sda1’ <0x2b2db680>
50 04/30/13 23:31:10.513 luup_log:41: dataMine: Error reading tmpfile during mountcheck <0x2b2db680>
06 04/30/13 23:31:10.514 Device_Variable::m_szValue_set device: 41 service: urn:cd-jackson-com:serviceId:DataMine1 variable: mountLocation was: /dev/sda1 now: #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2b2db680>
06 04/30/13 23:31:10.515 Device_Variable::m_szValue_set device: 41 service: urn:cd-jackson-com:serviceId:DataMine1 variable: mountType was: vfat now: #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2b2db680>
50 04/30/13 23:31:10.553 luup_log:41: dataMine: Mounting dataMine storage (/dev/sda1) to (/dataMine/) <0x2b2db680>
50 04/30/13 23:31:12.228 luup_log:41: dataMine: Mounted: /dev/sda1 on /dataMine type vfat (rw,relatime,fmask=0022,dmask=0022,codepage=cp437,iocharset=iso8859-1,shortname=mixed,errors=remount-ro) <0x2b2db680>
06 04/30/13 23:31:12.229 Device_Variable::m_szValue_set device: 41 service: urn:cd-jackson-com:serviceId:DataMine1 variable: mountLocation was: now: /dev/sda1 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2b2db680>
06 04/30/13 23:31:12.230 Device_Variable::m_szValue_set device: 41 service: urn:cd-jackson-com:serviceId:DataMine1 variable: mountType was: now: vfat #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2b2db680>
50 04/30/13 23:31:12.333 luup_log:41: dataMine: ERROR: Config file was zero length <0x2b2db680>
50 04/30/13 23:31:14.525 luup_log:41: dataMine: Primary config file load failed. Resorting to backup ‘/dataMine/dataMineConfig.json.Tue Apr 30 23-07-24 2013.backup’ LEAK this:98304 start:946176 to 0xe79000 <0x2b2db680>
09 04/30/13 23:31:52.668 JobHandler_LuaUPnP::Run device 41 dataMine graphing and logging room 0 type urn:schemas-cd-jackson-com:device:DataMine:1 id parent 0/0xaf5b18 upnp: 0 <0x2b6dd000>
50 04/30/13 23:32:02.997 luup_log:41: dataMine: Initialising dataMine System (0.976) <0x2c011680>
06 04/30/13 23:32:02.998 Device_Variable::m_szValue_set device: 41 service: urn:cd-jackson-com:serviceId:DataMine1 variable: ChannelCnt was: 0 now: 0 #hooks: 0 upnp: 0 v:0xbb2400/NONE duplicate:1 <0x2c011680>
06 04/30/13 23:32:02.998 Device_Variable::m_szValue_set device: 41 service: urn:cd-jackson-com:serviceId:DataMine1 variable: ChannelRec was: 0 now: 0 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1 <0x2c011680>
50 04/30/13 23:32:02.999 luup_log:41: dataMine: Mounting to UUID ‘4660-03E4’ <0x2c011680>
50 04/30/13 23:32:04.610 luup_log:41: dataMine: UUID = /dev/sda1: LABEL=“VERADISK” UUID=“4660-03E4” <0x2c011680>
50 04/30/13 23:32:04.650 luup_log:41: dataMine: Found UUID ‘4660-03E4’ at ‘/dev/sda1’ <0x2c011680>
50 04/30/13 23:32:04.718 luup_log:41: dataMine: Mounted: /dev/sda1 on /dataMine type vfat (rw,relatime,fmask=0022,dmask=0022,codepage=cp437,iocharset=iso8859-1,shortname=mixed,errors=remount-ro) <0x2c011680>
06 04/30/13 23:32:04.718 Device_Variable::m_szValue_set device: 41 service: urn:cd-jackson-com:serviceId:DataMine1 variable: mountLocation was: /dev/sda1 now: /dev/sda1 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1 <0x2c011680>
06 04/30/13 23:32:04.719 Device_Variable::m_szValue_set device: 41 service: urn:cd-jackson-com:serviceId:DataMine1 variable: mountType was: vfat now: vfat #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1 <0x2c011680>
50 04/30/13 23:32:04.790 luup_log:41: dataMine: ERROR: Config file was zero length <0x2c011680>
50 04/30/13 23:32:05.620 luup_log:41: dataMine: Primary config file load failed. Resorting to backup ‘/dataMine/dataMineConfig.json.Tue Apr 30 23-07-24 2013.backup’ LEAK this:8192 start:839680 to 0xf7a000 <0x2c011680>
09 04/30/13 23:40:39.261 JobHandler_LuaUPnP::Run device 41 dataMine graphing and logging room 0 type urn:schemas-cd-jackson-com:device:DataMine:1 id parent 0/0xb0cb30 upnp: 0 <0x2b4bf000>
50 04/30/13 23:40:47.603 luup_log:41: dataMine: Initialising dataMine System (0.976) <0x2bdf3680>
06 04/30/13 23:40:47.604 Device_Variable::m_szValue_set device: 41 service: urn:cd-jackson-com:serviceId:DataMine1 variable: ChannelCnt was: 0 now: 0 #hooks: 0 upnp: 0 v:0xbc9448/NONE duplicate:1 <0x2bdf3680>
06 04/30/13 23:40:47.605 Device_Variable::m_szValue_set device: 41 service: urn:cd-jackson-com:serviceId:DataMine1 variable: ChannelRec was: 0 now: 0 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1 <0x2bdf3680>
50 04/30/13 23:40:47.605 luup_log:41: dataMine: Mounting to UUID ‘4660-03E4’ <0x2bdf3680>
50 04/30/13 23:40:48.025 luup_log:41: dataMine: UUID = /dev/sda1: LABEL=“VERADISK” UUID=“4660-03E4” <0x2bdf3680>
50 04/30/13 23:40:48.052 luup_log:41: dataMine: Found UUID ‘4660-03E4’ at ‘/dev/sda1’ <0x2bdf3680>
50 04/30/13 23:40:48.078 luup_log:41: dataMine: Mounted: /dev/sda1 on /dataMine type vfat (rw,relatime,fmask=0022,dmask=0022,codepage=cp437,iocharset=iso8859-1,shortname=mixed,errors=remount-ro) <0x2bdf3680>
06 04/30/13 23:40:48.078 Device_Variable::m_szValue_set device: 41 service: urn:cd-jackson-com:serviceId:DataMine1 variable: mountLocation was: /dev/sda1 now: /dev/sda1 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1 <0x2bdf3680>
06 04/30/13 23:40:48.079 Device_Variable::m_szValue_set device: 41 service: urn:cd-jackson-com:serviceId:DataMine1 variable: mountType was: vfat now: vfat #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1 <0x2bdf3680>
50 04/30/13 23:40:48.106 luup_log:41: dataMine: ERROR: Config file was zero length <0x2bdf3680>
50 04/30/13 23:40:48.431 luup_log:41: dataMine: Primary config file load failed. Resorting to backup ‘/dataMine/dataMineConfig.json.Tue Apr 30 23-07-24 2013.backup’ LEAK this:237568 start:815104 to 0xf8b000 <0x2bdf3680>

Looking at the logs, the config file “dataMine Config.json” appears to be corrupted (reporting as zero length). It says it’s trying to revert to a backup config file - this was something I added a version or two ago, and while it tested ok, it may not be 100%. The other option is that the backup file it’s trying to use “'/dataMine/dataMineConfig.json.Tue Apr 30 23-07-24 2013.backup” may also be bad.

If you have WinSCP, it would be worth taking a look in the dataMine directory to see if there’s a problem with these files.

I’ll take a look at the code as at first look it seems strange to me that there are no further messages after the “reverting to backup” message.

Chris

I retested the revert to backup, and it worked ok here. However, the fact that the last message in your log each time dataMine starts is the reverting to backup entry, leads me to think that it’s crashing in there somewhere, but your log dump isn’t showing the log entry of interest.

If you can open the log manually in an editor (ie WinSCP) then look for the line that shows “Primary config file load failed” and see if there’s something in the next few lines that looks “bad” - it might say something like “LuaInterface::StartEngine failed” followed by an error message.

I suspect that your backup file may also be corrupted in some way, but not in a way that I detect. If you can send me a copy of the file, this might be useful in fixing this in future.

If we assume that both the main config file, and the last backup are corrupt, you could try removing these and let dataMine find the next one - the question really is if these are corrupted (possibly due to some USB issues) then others may also be…

Chris

cool. will dig out and post soon.

thanks.