Data yours stops gathering

Hi

My datayours (or at least the graphing) stopped updating a couple of days back. Where do I go to start troubleshooting?

Cheers

C

The first stop for diagnostics is the device control page where you should find links to the configuration and status of DataWatcher, DataCache, and DataGraph.

DataWatcher should tell you in the tally table how many new data values it has seen, whereas DataCache will tell you how many it has received and stored.

Beyond that, I’d need to more more about your configuration… is this Vera or openLuup, are you using AltUI, if so, are you using the Data Storage Provder push functionality there, …

Anything of interest in the log?

Hi
It’s vera plus, standard UI

only thing I have on the control page is;

Graph Cache Dash Watch

6 metrics

If you like this plugin, you could DONATE to Cancer Research UK right here

Which seems wrong…

Only thing I can see in the logs is the memory usage?

Any help?

Cheers

C

What version are you running of DataYours?

Current Version:

8.20160129

Latest Version

N/A

I shall update it

No difference…
C

Fixed on reboot

Cheers

C

:upside_down_face:

1 Like

I’m now running into the same situation…I see this in the cache page…

DAEMON = {
VERSION = _VERSION,
client = "DataCache",
destinations = {},
errors = {
count = 1,
message = "ERROR: address already in use",
time = "Fri Feb 12 02:13:11 2021"

I would appreciate some help in finding out what the error message means and how to trouble shoot the problem. Was logging fine for over a year, and in the last few days I get this error and logging stops. The only thing that will fix it is a reboot of vera (not a luup reload). But, the error returns in several hours. Where should I look first. What does ‘address’ pertain to?

Thanks.

Tell me something more about your configuration. Something must have changed recently, because DataYours certainly hasn’t.

Lets see…recently installed Virtual HTTP Devices plug-in, but am not using it; I found a different way to control some Wi-Fi LED strips. I implemented control of the Wi-Fi LED strips using curl inside a os.execute lua command inside of PLEG. I also have a new Yamaha receiver, so I have another instance of that plug-in, I did disconnect the old one and it is off the network.

That’s about all I’ve done in the last month or so. I’m not sure that the Data Cache address is referring to; maybe there is a conflict that has arisen? But, not sure what address I should check (IP, port, MAC, where the data is going, where the data is generated, etc.)

Any thoughts? As you know I’m also trying to resolve this problem by moving to Historian on OpenLuup. But, don’t like unsolved problems.

I’d like to see:

  • the device variables page
  • the start of the main log after a restart.

It’s probably the port which the error message is referring to. It needs to set up a watch for incoming UDP datagrams with the new incoming values. It shouldn’t be a conflict (unless you somehow have two copies running.) Is this on Vera or openLuup?

For reference, the part of my log showing DataYours startup is herE:

2021-02-13 17:08:01.426   luup_log:130: DataYours: starting...
2021-02-13 17:08:01.426   luup.variable_set:: 130.urn:akbooer-com:serviceId:DataYours1.StartTime was: Tue Feb  9 18:18:02 2021 now: Sat Feb 13 17:08:01 2021 #hooks:0
2021-02-13 17:08:01.427   luup.variable_set:: 130.urn:upnp-org:serviceId:altui1.DisplayLine1 was: Graph Cache Watch now: no services #hooks:0
2021-02-13 17:08:01.427   luup.variable_set:: 130.urn:upnp-org:serviceId:altui1.DisplayLine2 was: 412 metrics now: no database #hooks:0
2021-02-13 17:08:01.427   luup_log:130: DataYours: starting heartbeat
2021-02-13 17:08:01.436   luup.variable_set:: 130.urn:upnp-org:serviceId:altui1.DisplayLine2 was: no database now: 412 metrics #hooks:0
2021-02-13 17:08:01.437   luup.variable_set:: 130.urn:akbooer-com:serviceId:DataYours1.AppMemoryUsed was: 12819 now: 5193 #hooks:0
2021-02-13 17:08:01.476   luup_log:130: DataYours: starting services
2021-02-13 17:08:01.476   luup_log:130: DataYours:  service: Graph - L_DataGraph
2021-02-13 17:08:01.501   luup.register_handler:: global_function_name=HTTP_DataGraph, request=DataGraph
2021-02-13 17:08:01.502   luup.register_handler:: global_function_name=HTTP_DataGraphRenderer, request=render
2021-02-13 17:08:01.502   luup.register_handler:: global_function_name=HTTP_DataGraphRenderer, request=grafana/render
2021-02-13 17:08:01.502   luup_log:130: DataYours:  service: Cache - L_DataCache
2021-02-13 17:08:01.504   luup.register_handler:: global_function_name=HTTP_DataCache, request=DataCache
2021-02-13 17:08:01.505   luup_log:130: DataYours:  service: Watch - L_DataWatcher
2021-02-13 17:08:01.509   luup_log:130: DataDaemon: unable to open /www/DataWatcher.conf
2021-02-13 17:08:01.509   luup_log:130: DataDaemon: unable to open /www/DataTranslation.conf
2021-02-13 17:08:01.509   luup.register_handler:: global_function_name=HTTP_DataWatcher, request=DataWatcher
2021-02-13 17:08:01.510   luup_log:130: DataWatcher: starting variable watch...
2021-02-13 17:08:01.510   luup.register_handler:: global_function_name=HTTP_DataWatcherRelay, request=DataWatcherRelay
2021-02-13 17:08:01.510   luup_log:130: DataWatcher: registering with AltUI [3] as Data Storage Provider
2021-02-13 17:08:01.511   luup.call_action:: 3.urn:upnp-org:serviceId:altui1.RegisterDataProvider 
2021-02-13 17:08:01.511   luup_log:130: DataYours: ...startup complete

I’d also like to see the log when the error occurs, but you say that this happens after a few hours?

DataYours variable page:

DataYours startup…

50	02/13/21 11:34:17.289	luup_log:10: DataYours: starting... <0x76ef6520>
06	02/13/21 11:34:17.290	Device_Variable::m_szValue_set device: 10 service: urn:akbooer-com:serviceId:DataYours1 variable: StartTime was: Fri Feb 12 22:39:18 2021 now: Sat Feb 13 11:34:17 2021 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x76ef6520>
06	02/13/21 11:34:17.290	Device_Variable::m_szValue_set device: 10 service: urn:upnp-org:serviceId:altui1 variable: DisplayLine1 was: Graph Cache Dash Watch now: no services #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x76ef6520>
06	02/13/21 11:34:17.291	Device_Variable::m_szValue_set device: 10 service: urn:upnp-org:serviceId:altui1 variable: DisplayLine2 was: 21 metrics now: no database #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x76ef6520>
50	02/13/21 11:34:17.291	luup_log:10: DataYours: starting heartbeat <0x76ef6520>
06	02/13/21 11:34:17.293	Device_Variable::m_szValue_set device: 10 service: urn:upnp-org:serviceId:altui1 variable: DisplayLine2 was: no database now: [string "-------------------------------------------..."]:94: cannot open /nas/whisper/: No such file or directory #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x76ef6520>
06	02/13/21 11:34:17.294	Device_Variable::m_szValue_set device: 10 service: urn:akbooer-com:serviceId:DataYours1 variable: AppMemoryUsed was: 566 now: 215 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x76ef6520>
50	02/13/21 11:34:17.297	luup_log:10: DataYours: starting services <0x76ef6520>
50	02/13/21 11:34:17.297	luup_log:10: DataYours:  service: Graph - L_DataGraph <0x76ef6520>
50	02/13/21 11:34:17.352	luup_log:10: DataYours:  service: Cache - L_DataCache <0x76ef6520>
50	02/13/21 11:34:17.363	luup_log:10: DataYours:  service: Dash - L_DataDash <0x76ef6520>
50	02/13/21 11:34:17.402	luup_log:10: ERROR: unable to open /www/DataDash.conf <0x76ef6520>
50	02/13/21 11:34:17.423	luup_log:10: DataDash: DataDash7 daemon started <0x76ef6520>
50	02/13/21 11:34:17.423	luup_log:10: DataYours:  service: Watch - L_DataWatcher <0x76ef6520>
50	02/13/21 11:34:17.440	luup_log:10: ERROR: unable to open /www/DataTranslation.conf <0x76ef6520>
50	02/13/21 11:34:17.441	luup_log:10: DataWatcher: starting variable watch... <0x76ef6520>
50	02/13/21 11:34:17.444	luup_log:10: DataWatcher: starting memory watch... <0x76ef6520>
50	02/13/21 11:34:17.446	luup_log:10: DataWatcher: registering with AltUI [13] as Data Storage Provider <0x76ef6520>
08	02/13/21 11:34:17.448	JobHandler_LuaUPnP::HandleActionRequest device: 13 service: urn:upnp-org:serviceId:altui1 action: RegisterDataProvider <0x76ef6520>
08	02/13/21 11:34:17.448	JobHandler_LuaUPnP::HandleActionRequest argument newUrl=http://127.0.0.1:3480/data_request?id=lr_DataWatcherRelay&target={0} <0x76ef6520>
08	02/13/21 11:34:17.448	JobHandler_LuaUPnP::HandleActionRequest argument newName=datayours <0x76ef6520>
08	02/13/21 11:34:17.449	JobHandler_LuaUPnP::HandleActionRequest argument newJsonParameters=[{
 "default":"unknown",
 "key":"target",
 "label":"Metric Name",
 "type":"text"
},{
  "default":"http:\/\/192.168.XXX.XXX:3480\/data_request?id=lr_render&target={0}&hideLegend=true&height=250&from=-y",
 "key":"graphicurl",
 "label":"Graphic Url",
"type":"url"
}] <0x76ef6520>
02	02/13/21 11:34:17.449	Device_LuaUPnP::HandleActionRequest 13 not ready 0xc1fd18 <0x76ef6520>
50	02/13/21 11:34:17.449	luup_log:10: DataYours: ...startup complete <0x76ef6520>
06	02/13/21 11:34:17.450	Device_Variable::m_szValue_set device: 10 service: urn:upnp-org:serviceId:altui1 variable: DisplayLine1 was: no services now: Graph Cache Dash Watch #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x76ef6520>
50	02/13/21 11:34:17.571	luup_log:0: cifsmount: '//192.168.XXX.XXX/SkogenDataYours' mounted status: nil <0x76ef6520>
50	02/13/21 11:34:17.572	luup_log:0: cifsmount: '//192.168.XXX.XXX/SkogenDataYours' mounted OK: 0 <0x76ef6520>

Hmm…Looks like DataYours started up before my CIFS mount. That doesn’t happen every time, sometimes it starts up in the desired order (CIFS mount then DataYours). BTW, I’m using code you shared for the CIFS mount in the Lua startup code.

But this doesn’t explain why I’m losing logging after several hours…I’ve checked the mount after data logging stops and the mount is ok. I’ll reboot vera again and see if the CIFS drive will mount before DataYours starts…

Happened in the same order after another Vera reboot

After several attempts, DataYours starts up before my CIFS mount, the DataCache error message is present and no logging. Is there any way to force DataYours to delay startup or to reinitialize it after the CIFS mount is complete?

That doesn’t seem to be it (DataYours starting before CIFS mount). Now, in the logs I see the CIFS mount has occured prior to DataYours starting. DataYours still showing the error…

50	02/13/21 21:56:36.135	luup_log:10: DataYours: starting services <0x76ea4520>
50	02/13/21 21:56:36.136	luup_log:10: DataYours:  service: Graph - L_DataGraph <0x76ea4520>
50	02/13/21 21:56:36.174	luup_log:10: DataYours:  service: Cache - L_DataCache <0x76ea4520>
50	02/13/21 21:56:36.184	luup_log:10: DataCache: ERROR: address already in use <0x76ea4520>
50	02/13/21 21:56:36.184	luup_log:10: DataYours:  service: Dash - L_DataDash <0x76ea4520>
50	02/13/21 21:56:36.214	luup_log:10: ERROR: unable to open /www/DataDash.conf <0x76ea4520>
50	02/13/21 21:56:36.255	luup_log:10: DataDash: DataDash7 daemon started <0x76ea4520>
50	02/13/21 21:56:36.256	luup_log:10: DataYours:  service: Watch - L_DataWatcher <0x76ea4520>
50	02/13/21 21:56:36.269	luup_log:10: ERROR: unable to open /www/DataTranslation.conf <0x76ea4520>

The files …DataDash.conf and DataTranslation.conf are presumably needed, correct. Perhaps my last Vera update wiped them out? Still,

50	02/13/21 21:56:36.184	luup_log:10: DataCache: ERROR: address already in use <0x76ea4520>

Can’t figure it out.

I can only think that something else is accessing the port on the machine.

You can check which ports are in use with a shell command. On one of my systems this gives:

# netstat -tulpn
Active Internet connections (only servers)
Proto Recv-Q Send-Q Local Address           Foreign Address         State       PID/Program name
tcp        0      0 0.0.0.0:11011           0.0.0.0:*               LISTEN      12068/lua5.1    
tcp        0      0 0.0.0.0:22              0.0.0.0:*               LISTEN      845/sshd        
tcp        0      0 127.0.0.1:3350          0.0.0.0:*               LISTEN      834/xrdp-sesman 
tcp        0      0 0.0.0.0:3480            0.0.0.0:*               LISTEN      12068/lua5.1    
tcp        0      0 0.0.0.0:2525            0.0.0.0:*               LISTEN      12068/lua5.1    
tcp        0      0 0.0.0.0:3389            0.0.0.0:*               LISTEN      808/xrdp        
tcp6       0      0 :::8080                 :::*                    LISTEN      868/apache2     
tcp6       0      0 :::22                   :::*                    LISTEN      845/sshd        
tcp6       0      0 :::3000                 :::*                    LISTEN      592/grafana-server
udp        0      0 0.0.0.0:5353            0.0.0.0:*                           573/avahi-daemon: r
udp        0      0 0.0.0.0:48142           0.0.0.0:*                           1212/dhclient   
udp        0      0 0.0.0.0:67              0.0.0.0:*                           1022/udhcpd     
udp        0      0 0.0.0.0:68              0.0.0.0:*                           1212/dhclient   
udp        0      0 0.0.0.0:59331           0.0.0.0:*                           573/avahi-daemon: r
udp6       0      0 :::5353                 :::*                                573/avahi-daemon: r
udp6       0      0 :::14371                :::*                                1212/dhclient   
udp6       0      0 :::49101                :::*                                573/avahi-daemon: r

I’m also very perplexed by your mount problems. The startup code should call the mount command synchronously and not return until it’s done. I’ve never seen a problem with doing this.

Additionally, the mount only occurs on the first Luup restart after a system reboot. Subsequent Luup restarts should not need to mount anything, since it’s already there. The code I wrote originally checks for this. Thus the target volume should always be mounted before DatsYours starts up. If, for some bizarre reason, it’s not, then a Luup restart, after the volume IS mounted successfully, should also fix the problem.

Well, definitely see that :2003 is being used…

Active Internet connections (only servers)
Proto Recv-Q Send-Q Local Address           Foreign Address         State       PID/Program name
tcp      129      0 0.0.0.0:49451           0.0.0.0:*               LISTEN      7700/lua
tcp        0      0 0.0.0.0:49453           0.0.0.0:*               LISTEN      25796/LuaUPnP
tcp        0      0 0.0.0.0:80              0.0.0.0:*               LISTEN      5830/lighttpd
tcp        0      0 0.0.0.0:53              0.0.0.0:*               LISTEN      3968/sh
tcp        0      0 0.0.0.0:22              0.0.0.0:*               LISTEN      6431/dropbear
tcp        0      0 0.0.0.0:3480            0.0.0.0:*               LISTEN      25796/LuaUPnP
tcp        0      0 :::53                   :::*                    LISTEN      3968/sh
tcp        0      0 :::22                   :::*                    LISTEN      6431/dropbear
udp        0      0 0.0.0.0:53              0.0.0.0:*                           3968/sh
udp        0      0 0.0.0.0:67              0.0.0.0:*                           3968/sh
udp        0      0 0.0.0.0:1900            0.0.0.0:*                           25796/LuaUPnP
udp   165760      0 0.0.0.0:1900            0.0.0.0:*                           7700/lua
udp        0      0 127.0.0.1:34717         0.0.0.0:*                           25796/LuaUPnP
udp        0      0 127.0.0.1:56513         0.0.0.0:*                           7700/lua
udp   164032      0 0.0.0.0:2003            0.0.0.0:*                           7700/lua
udp        0      0 :::546                  :::*                                3878/odhcp6c
udp        0      0 :::547                  :::*                                1836/odhcpd
udp        0      0 :::53                   :::*                                3968/sh

Any idea how to figure out what ‘7700/lua’ pertains to?

Okay, I tracked down PID 7700…

 7700     1 root     S     6480  2.5   1  0.0 lua /tmp/ezviz/ezviz_video_manage

What is this??? Could this have been part of the latest Vera update, some camera thing that I don’t use.

That may be it! Kill the process and see.

1 Like