Basic Event Logging Problems - TempLogFileSystemFailure

Hi All,

I am trying to write a very simple script (heavily borrowing from code discussed in this post:http://forum.micasaverde.com/index.php/topic,6489.msg40139.html#msg40139) that watches when a variable changes and logs the event via a GET request to a database on another server. Much like the Alternate Event Server (which doesn’t seems to behave as documented on the wiki in the current production firmware my Vera Lite came with [1.7.318])

When I tail the LuaUPnP.log file on the Vera Lite I notice that after a number of firings of my logging function the unit has the following error:

02 08/27/14 19:15:04.116 UserData::TempLogFileSystemFailure start <0x2c0fa680>

After this point my logging stops working.

The actual code being called is as follows:

function w_switch (lul_device, lul_service, lul_variable, lul_value_old, lul_value_new) url = ("http://192.168.0.113/alert?DeviceID=%s&Description=%s&OldValue=%s&NewValue=%s&UtcTs=%s"):format(tostring(lul_device), lul_variable, lul_value_old, lul_value_new, os.time()) luup.log(("TEST:: Logging update for sensor(%s). Current Memory Usage:%s"):format(tostring(lul_device),collectgarbage("count")*1024)) luup.inet.wget(url, 5) collectgarbage("collect") luup.log(("TEST:: Garbage Collected. Current Memory Usage:%s"):format(collectgarbage("count")*1024)) end

Below is a snippet of the log file where you can see the log events and bound function firing. I initially thought that I may be suffering some kind of memory problem which is why there are garbage collect calls in my logging function. Adding/removing these calls does not change the result.

50	08/27/14 19:14:37.894	luup_log:0: TEST:: Logging update for sensor(3). Current Memory Usage:42891 <0x2befa680>
50	08/27/14 19:14:37.934	luup_log:0: TEST:: Garbage Collected. Current Memory Usage:42641 <0x2befa680>
50	08/27/14 19:14:37.935	luup_log:0: TEST:: Logging update for sensor(3). Current Memory Usage:42778 <0x2befa680>
50	08/27/14 19:14:37.963	luup_log:0: TEST:: Garbage Collected. Current Memory Usage:42641 <0x2befa680>
06	08/27/14 19:14:37.964	Device_Variable::m_szValue_set device: 3 service: urn:micasaverde-com:serviceId:SecuritySensor1 variable: ArmedTripped was: 0 now: 0 #hooks: 0 upnp: 0 v:0xbe5718/DL_ARMEDTRIPPED duplicate:1 <0x2befa680>
06	08/27/14 19:14:37.964	Device_Variable::m_szValue_set device: 3 service: urn:micasaverde-com:serviceId:SecuritySensor1 variable: LastTrip was: 1409192040 now: 1409192077 #hooks: 0 upnp: 0 v:0xbd49b0/NONE duplicate:0 <0x2befa680>
01	08/27/14 19:15:04.115	UserData::WriteUserData saved--before move File Size: 4559 save size 4559 <0x2c0fa680>
02	08/27/14 19:15:04.116	UserData::TempLogFileSystemFailure start <0x2c0fa680>
02	08/27/14 19:15:04.139	UserData::TempLogFileSystemFailure 4329
-rw-r--r--    1 root     root            33 Aug 26 20:28 /etc/cmh/HW_Key
-rw-r--r--    1 root     root            33 Aug 26 20:23 /etc/cmh/HW_Key2
-rw-r--r--    1 root     root             9 Aug 26 20:28 /etc/cmh/PK_AccessPoint

I don’t know if or how my code is creating this problem. Any advice would be appreciated.

Thanks,
BusinessTime

Did you have any luck figuring this out?

I’m seeing similar failures in my logs.

06 09/29/14 17:14:14.356 Device_Variable::m_szValue_set device: 41 service: urn:micasaverde-com:serviceId:EnergyMetering1 variable: KWH was: 80.4380 now: 80.4380 #hooks: 0 upnp: 0 skip: 0 v:0xcee3c8/NONE duplicate:1 <0x2b91c680> 06 09/29/14 17:14:14.357 Device_Variable::m_szValue_set device: 41 service: urn:micasaverde-com:serviceId:EnergyMetering1 variable: KWHReading was: 1412036053 now: 1412036054 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x2b91c680> 01 09/29/14 17:14:22.283 UserData::WriteUserData saved--before move File Size: 47177 save size 47177 __LEAK__ this:262144 start:491520 to 0x1112000 <0x2bb1c680> 02 09/29/14 17:14:22.284 UserData::TempLogFileSystemFailure start <0x2bb1c680> 02 09/29/14 17:14:22.311 UserData::TempLogFileSystemFailure 5922 -rw-r--r-- 1 root root 33 Sep 28 21:27 /etc/cmh/HW_Key -rw-r--r-- 1 root root 33 Jun 27 2013 /etc/cmh/HW_Key2 ...

I saw th? dame error un m’y logs yesterday acter upgrading tout UI7.

I too am seeing “UserData::TempLogFileSystemFailure” with disturbing frequency (every 6 minutes in some cases). Vera recovers, but these errors are still a concern. I’m running UI7.

02 10/19/14 13:03:12.499 UserData::TempLogFileSystemFailure start <0x2b826680>
02 10/19/14 13:03:12.532 UserData::TempLogFileSystemFailure 5490
02 10/19/14 13:03:12.553 UserData::TempLogFileSystemFailure start <0x2b826680>
02 10/19/14 13:03:12.582 UserData::TempLogFileSystemFailure 5401
02 10/19/14 13:18:18.488 UserData::TempLogFileSystemFailure start <0x2c024680>
02 10/19/14 13:18:18.516 UserData::TempLogFileSystemFailure 5490
02 10/19/14 13:18:18.542 UserData::TempLogFileSystemFailure start <0x2c024680>
02 10/19/14 13:18:18.571 UserData::TempLogFileSystemFailure 5401
02 10/19/14 13:24:18.446 UserData::TempLogFileSystemFailure start <0x2c024680>
02 10/19/14 13:24:18.475 UserData::TempLogFileSystemFailure 5490
02 10/19/14 13:24:18.509 UserData::TempLogFileSystemFailure start <0x2c024680>
02 10/19/14 13:24:18.540 UserData::TempLogFileSystemFailure 5401
02 10/19/14 13:43:24.456 UserData::TempLogFileSystemFailure start <0x2b482680>
02 10/19/14 13:43:24.484 UserData::TempLogFileSystemFailure 5490
02 10/19/14 13:43:24.508 UserData::TempLogFileSystemFailure start <0x2b482680>
02 10/19/14 13:43:24.536 UserData::TempLogFileSystemFailure 5401
02 10/19/14 13:49:24.419 UserData::TempLogFileSystemFailure start <0x2b482680>
02 10/19/14 13:49:24.447 UserData::TempLogFileSystemFailure 5490
02 10/19/14 13:49:24.472 UserData::TempLogFileSystemFailure start <0x2b482680>
02 10/19/14 13:49:24.500 UserData::TempLogFileSystemFailure 5401
02 10/19/14 13:55:24.462 UserData::TempLogFileSystemFailure start <0x2b482680>
02 10/19/14 13:55:24.490 UserData::TempLogFileSystemFailure 5490
02 10/19/14 13:55:24.510 UserData::TempLogFileSystemFailure start <0x2b482680>
02 10/19/14 13:55:24.538 UserData::TempLogFileSystemFailure 5401
02 10/19/14 14:01:24.515 UserData::TempLogFileSystemFailure start <0x2b482680>
02 10/19/14 14:01:24.543 UserData::TempLogFileSystemFailure 5490
02 10/19/14 14:01:24.565 UserData::TempLogFileSystemFailure start <0x2b482680>
02 10/19/14 14:01:24.593 UserData::TempLogFileSystemFailure 5401

I removed my USB drive thinking it may have caused the errors. Since UI7 is very confusing with regard to using a USB drive, it might be that part of my OS still thinks I’m using a USB drive…

I am also getting these “UserData::TempLogFileSystemFailure” errors in my log frequently and the Luup engine is crashing as well. This is on a Vera3 running 1.7.388. Does anyone have any more information about this?

Thanks,
watou

Same log message here on 1.7.439.

I have the same issue as well

Same issue here on latest UI7 and crashing every few hours…

I also see this in my logs, just as hmspain said, sometimes every 6 minutes. It may always be every 6 minutes. I originally thought it was a major issue but everything works as far as I can tell. I searched around here a bit and found some notes about Vera saving userdata every 6 or 7 minutes and I thought that may be associated. I have about 50 tabs open right now researching some other Vera stuff but if I come across those other threads I will post back.

I went back to using Vera Alerts (UI7 compatible now) so I’m now notified when my Vera restarts… which is often. I run out of log file, so I can’t debug the restarts… back to using a USB drive. The good news is the USB drive “enabled” without a lot of pain. The bad news is the Vera restarts and the cryptic "TempLogFileSystemFailure"s are all over my log file.

When this happens, the system become totally unresponsive which might account for some of the perceived “delays”.

Sure would like to hear from MCV on this one! I’ll try opening a trouble ticket; it is what I would ask myself to do (I’m in support too).

I went back to using Vera Alerts (UI7 compatible now) so I’m now notified when my Vera restarts… which is often. I run out of log file, so I can’t debug the restarts… back to using a USB drive. The good news is the USB drive “enabled” without a lot of pain. The bad news is the Vera restarts and the cryptic "TempLogFileSystemFailure"s are all over my log file.

When this happens, the system become totally unresponsive which might account for some of the perceived “delays”.

Sure would like to hear from MCV on this one! I’ll try opening a trouble ticket; it is what I would ask myself to do (I’m in support too).[/quote]

Good call on the Vera Alerts! I had turned that off some time ago when I first set it up because it was often and annoying. I made sure I had plenty of space on my Vera and turned it back on. So far I only have 1 restart today.

I filed another trouble ticket on the “TempLogFileSystemFailure” error which seems to cause the Vera to crash (at least it’s restarting!). Nothing from MCV yet…

I filed a trouble ticket a couple weeks back, but support is hit and miss. I think they have a helpdesk agent that just trashes requests, counts them as work, and goes about collecting a paycheck. A long time ago, I had a job where we found a closet stuffed with old (unanswered) trouble tickets…

[quote=“hmspain, post:12, topic:182683”]I filed another trouble ticket on the “TempLogFileSystemFailure” error which seems to cause the Vera to crash (at least it’s restarting!). Nothing from MCV yet…

I filed a trouble ticket a couple weeks back, but support is hit and miss. I think they have a helpdesk agent that just trashes requests, counts them as work, and goes about collecting a paycheck. A long time ago, I had a job where we found a closet stuffed with old (unanswered) trouble tickets…[/quote]

The “TempLogFileSystemFailure” is part of the LuaUPnP image. If MCV posts the code, we could perhaps debug it further :-).

Is this in any way related to log rotation? Seems like I see this sometimes if my space is getting low and logs are rotating quickly. If I could get my LuaUPnP.log tailed over to my syslog this would be a lot easier to watch.

I think I disabled log file rotation, at least the cron job that says it rotates the logs :).

crontab -e

No impact on the number of crashes…

Thanks for the idea on the crontab! I poked around at some of the .sh files and it seems changing the rotation schedule wouldn’t be very hard. I am more interested in getting my Lua log over to my syslog so I can keep a better eye on the history. I did a test with:

while true do tail lualog | logger -t ‘Luup’

That worked well at casting my log into syslog, but of course only runs when I perform that command directly in the terminal. I did notice some odd behavior from this, perhaps from too much logging going on, but it can be grep for finer control. Does anyone think it would be an issue to have this running all the time? I was also considering modifying the files required to just push the lualog out on syslog, but that route seems slightly more complicated.

Any news on this?

I am experiencing the same problems: “Cannot write user data” every six minutes. After a restart, it is usually gone for a few hours, but then the problems start again. Everything keeps working fine though, and I don’t get unexpected restarts. But it is very annoying and gives me the feeling something is not right. Moreover, I cannot use the alerts overview on my Dashboard anymore, since it is always filled with 10 times the same message.

I have sent an email to Vera support as well, hopefully they can help me. But any help from other users is also very welcome!

Same problem here too, after installing latest firmware and moving my whisper data and logs to the same usb stick.

I’ve been seeing this frequently without any USB stick logging - several times per hour

Yes I thin k you’re right. I’ve moved the logs to another flash-drive,but it’s still happening.
Support told me it could be one of my (not in use/un-reachable/plugin) camera’s, so I’ve removed them for now.
But the message is still here.