Problems running in a RPi

Functionality and usage of the OpenNethome Server
Post Reply
krambriw
Posts: 86
Joined: Sun Jan 04, 2015 8:48 am

Problems running in a RPi

Post by krambriw »

Hello,
I'm running OpenNetHome in a Raspberry Pi and I see a problem that it stops updating events via the TCP port after about a week. See the error message from a telnet session below. A restart of OpenNetHome or a reboot is then necessary.

Code: Select all

event,NexaL_Message,Direction,In,NexaL.Address,1439990,NexaL.Button,10,NexaL.Command,1,Value,
event,NexaL_Message,Direction,In,NexaL.Address,1439990,NexaL.Button,10,NexaL.Command,0,Value,
event,NexaL_Message,Direction,In,NexaL.Address,1439990,NexaL.Button,10,NexaL.Command,0,Value,
event,NexaL_Message,Direction,In,NexaL.Address,1439990,NexaL.Button,10,NexaL.Command,0,Value,
event,NexaL_Message,Direction,In,NexaL.Address,1439990,NexaL.Button,9,NexaL.Command,0,Value,
event,NexaL_Message,Direction,In,NexaL.Address,1439990,NexaL.Button,10,NexaL.Command,0,Value,
event,NexaL_Message,Direction,In,NexaL.Address,1439990,NexaL.Button,10,NexaL.Command,0,Value,
event,Oregon_Message,Direction,In,Oregon.Channel,4,Oregon.Id,112,Oregon.LowBattery,0,Oregon.Moisture,55,Oregon.SensorId,7456,Oregon.Temp,109,Value,
event,Oregon_Message,Direction,In,Oregon.Channel,4,Oregon.Id,112,Oregon.LowBattery,0,Oregon.Moisture,55,Oregon.SensorId,7456,Oregon.Temp,109,Value,
event,UPnP_Creation_Message,DeviceType,urn:schemas-upnp-org:device:InternetGatewayDevice:1,Direction,In,FriendlyName,DIR-655,Location,http://192.168.10.254:6553
0/rootDesc.xml,ModelName,D-Link Router,SerialNumber,209,UDN,uuid:6ae3b6fa-1dd2-11b2-b842-80c6e3a145f6,Value,
event,Alarm,Value,Failed reading from socket in TCPCommandPort java.net.SocketException: Invalid argument
Top
stefangsbb
Site Admin
Posts: 313
Joined: Sun Nov 30, 2014 2:16 pm

Re: Problems running in a RPi

Post by stefangsbb »

Is this something that has started happen recently? If there is more information about the exception in the log file, could you please send that so I can have a look.
Top
krambriw
Posts: 86
Joined: Sun Jan 04, 2015 8:48 am

Re: Problems running in a RPi

Post by krambriw »

No, I don't think it is recent, I see that have a bunch of logfiles created approx one week apart that have basically the same content but I have not really digged into the problem too much

The logfiles (I'll mail you a zip) are scattered with the same type of log entries

Code: Select all

2015.10.28 05:17:35.685 WARNING:TCPCommandPort could not send event, TCP stream blocked (TCPCommandPort 12889282, TID16) 
2015.10.28 05:17:35.689 WARNING:TCPCommandPort could not send event, TCP stream blocked (TCPCommandPort 12889283, TID16) 
2015.10.28 05:17:35.693 WARNING:TCPCommandPort could not send event, TCP stream blocked (TCPCommandPort 12889284, TID16) 
2015.10.28 05:17:35.696 WARNING:TCPCommandPort could not send event, TCP stream blocked (TCPCommandPort 12889285, TID16) 
2015.10.28 05:17:35.700 WARNING:TCPCommandPort could not send event, TCP stream blocked (TCPCommandPort 12889286, TID16) 
2015.10.28 05:17:35.703 WARNING:TCPCommandPort could not send event, TCP stream blocked (TCPCommandPort 12889287, TID16) 
2015.10.28 05:17:35.707 WARNING:TCPCommandPort could not send event, TCP stream blocked (TCPCommandPort 12889288, TID16)
and sometimes

Code: Select all

2015.10.28 05:17:56.464 WARNING:Failed reading from socket in TCPCommandPort java.net.SocketException: Connection reset (TCPCommandPort$Session 12894030, TID1909) 
2015.10.28 05:17:56.477 INFO:Disconnected from 192.168.10.2 (TCPCommandPort$Session 12894031, TID1909) 
2015.10.28 05:17:56.481 SEVERE:Event queue full. Current Item processing is "TCP Command Port"  since 27.00 ms (HomeServer 12894032, TID16)

After a fresh start

Code: Select all

2015.10.28 06:15:17.21 INFO:**Starting HomeManager 2.1-SNAPSHOT-f6c4e** (HomeManagerStarter 0, TID1) 
2015.10.28 06:16:25.855 INFO:Logging to: /var/log/nethome/HomeManager%g.log (HomeManagerStarter 1, TID1) 
2015.10.28 06:16:26.387 WARNING:Prefs file removed in background /home/nethome/.java/.userPrefs/nu/nethome/home/impl/prefs.xml (FileSystemPreferences$6 2, TID1) 
2015.10.28 06:16:26.428 INFO:Loading Items from /etc/opt/nethome/config.xml (HomeItemFileLoader 3, TID1) 
2015.10.28 06:16:39.172 WARNING:Failed to load Item nr41from file. Could not create class: UsbScanner (HomeItemFileLoader 4, TID1) 
2015.10.28 06:16:42.289 WARNING:Failed to find COM Port: COM14 (TellstickPort$SerialDevice 5, TID1) 
2015.10.28 06:16:42.327 WARNING:failed to open serial port to Tellstick: COM14 (Tellstick 6, TID1) 
java.io.IOException: Failed to find COM Port: COM14
	at nu.nethome.home.items.tellstick.TellstickPort$SerialDevice.<init>(TellstickPort.java:102)
	at nu.nethome.home.items.tellstick.TellstickPort.<init>(TellstickPort.java:236)
	at nu.nethome.home.items.tellstick.Tellstick.createTellstickPort(Tellstick.java:187)
	at nu.nethome.home.items.tellstick.Tellstick.activate(Tellstick.java:182)
	at nu.nethome.home.item.HomeItemAdapter.activate(HomeItemAdapter.java:70)
	at nu.nethome.home.impl.HomeServer.loadItems(HomeServer.java:477)
	at nu.nethome.home.impl.HomeServer.run(HomeServer.java:182)
	at nu.nethome.home.impl.HomeManagerStarter.go(HomeManagerStarter.java:139)
	at nu.nethome.home.start.StaticHomeManagerStarter.main(StaticHomeManagerStarter.java:32)
2015.10.28 06:16:49.340 INFO:Sample Rate:44100.0 (AudioProtocolPort 7, TID26) 
2015.10.28 06:17:02.405 INFO:Activated 27 of 27 Items (HomeServer 8, TID1) 
2015.10.28 06:17:13.619 INFO:Connection from 127.0.0.1 (TCPCommandPort 9, TID17) 
2015.10.28 06:21:32.13 INFO:Connection from 192.168.10.2 (TCPCommandPort 10, TID17)
(not finding a Tellstick is expected since it is not connected, )

Kind regards, Walter
Top
stefangsbb
Site Admin
Posts: 313
Joined: Sun Nov 30, 2014 2:16 pm

Re: Problems running in a RPi

Post by stefangsbb »

Thanks for the feedback, I will look into this and see what I can find
Top
krambriw
Posts: 86
Joined: Sun Jan 04, 2015 8:48 am

Re: Problems running in a RPi

Post by krambriw »

Seems you still have a problem going into intensive loop in the event queue

Code: Select all

2015.11.06 05:21:01.261 WARNING:TCPCommandPort could not send event, TCP stream blocked (TCPCommandPort 22179160, TID18) 
2015.11.06 05:21:01.264 WARNING:TCPCommandPort could not send event, TCP stream blocked (TCPCommandPort 22179161, TID18) 
2015.11.06 05:21:01.268 WARNING:TCPCommandPort could not send event, TCP stream blocked (TCPCommandPort 22179162, TID18) 
2015.11.06 05:21:01.271 WARNING:TCPCommandPort could not send event, TCP stream blocked (TCPCommandPort 22179163, TID18) 
2015.11.06 05:21:01.275 WARNING:TCPCommandPort could not send event, TCP stream blocked (TCPCommandPort 22179164, TID18) 
2015.11.06 05:21:01.278 WARNING:TCPCommandPort could not send event, TCP stream blocked (TCPCommandPort 22179165, TID18) 
2015.11.06 05:21:01.283 WARNING:TCPCommandPort could not send event, TCP stream blocked (TCPCommandPort 22179166, TID18) 
2015.11.06 05:21:01.288 WARNING:TCPCommandPort could not send event, TCP stream blocked (TCPCommandPort 22179167, TID18) 
2015.11.06 05:21:01.293 WARNING:TCPCommandPort could not send event, TCP stream blocked (TCPCommandPort 22179168, TID18) 
2015.11.06 05:21:01.298 WARNING:TCPCommandPort could not send event, TCP stream blocked (TCPCommandPort 22179169, TID18) 
2015.11.06 05:21:01.302 WARNING:TCPCommandPort could not send event, TCP stream blocked (TCPCommandPort 22179170, TID18) 
2015.11.06 05:21:01.308 WARNING:TCPCommandPort could not send event, TCP stream blocked (TCPCommandPort 22179171, TID18) 
2015.11.06 05:21:01.312 WARNING:TCPCommandPort could not send event, TCP stream blocked (TCPCommandPort 22179172, TID18) 
2015.11.06 05:21:01.316 WARNING:TCPCommandPort could not send event, TCP stream blocked (TCPCommandPort 22179173, TID18) 
2015.11.06 05:21:01.320 WARNING:TCPCommandPort could not send event, TCP stream blocked (TCPCommandPort 22179174, TID18) 
2015.11.06 05:21:01.328 SEVERE:Event queue full. Current Item processing is "TCP Command Port"  since 2.97 ms (HomeServer 22179176, TID18) 
2015.11.06 05:21:01.325 WARNING:TCPCommandPort could not send event, TCP stream blocked (TCPCommandPort 22179175, TID18) 
2015.11.06 05:21:01.333 WARNING:TCPCommandPort could not send event, TCP stream blocked (TCPCommandPort 22179177, TID18) 
2015.11.06 05:21:01.337 WARNING:TCPCommandPort could not send event, TCP stream blocked (TCPCommandPort 22179178, TID18) 
2015.11.06 05:21:01.342 WARNING:TCPCommandPort could not send event, TCP stream blocked (TCPCommandPort 22179179, TID18) 
2015.11.06 05:21:01.348 WARNING:TCPCommandPort could not send event, TCP stream blocked (TCPCommandPort 22179180, TID18) 
2015.11.06 05:21:01.351 WARNING:TCPCommandPort could not send event, TCP stream blocked (TCPCommandPort 22179181, TID18) 
2015.11.06 05:21:01.355 WARNING:TCPCommandPort could not send event, TCP stream blocked (TCPCommandPort 22179182, TID18) 
2015.11.06 05:21:01.358 WARNING:TCPCommandPort could not send event, TCP stream blocked (TCPCommandPort 22179183, TID18) 
2015.11.06 05:21:01.362 WARNING:TCPCommandPort could not send event, TCP stream blocked (TCPCommandPort 22179184, TID18) 
2015.11.06 05:21:01.365 WARNING:TCPCommandPort could not send event, TCP stream blocked (TCPCommandPort 22179185, TID18) 
2015.11.06 05:21:01.369 WARNING:TCPCommandPort could not send event, TCP stream blocked (TCPCommandPort 22179186, TID18) 
2015.11.06 05:21:01.372 WARNING:TCPCommandPort could not send event, TCP stream blocked (TCPCommandPort 22179187, TID18) 
2015.11.06 05:21:01.376 WARNING:TCPCommandPort could not send event, TCP stream blocked (TCPCommandPort 22179188, TID18) 
2015.11.06 05:21:01.379 WARNING:TCPCommandPort could not send event, TCP stream blocked (TCPCommandPort 22179189, TID18) 
2015.11.06 05:21:01.388 WARNING:TCPCommandPort could not send event, TCP stream blocked (TCPCommandPort 22179190, TID18) 
2015.11.06 05:21:01.392 WARNING:TCPCommandPort could not send event, TCP stream blocked (TCPCommandPort 22179191, TID18) 
2015.11.06 05:21:01.395 WARNING:TCPCommandPort could not send event, TCP stream blocked (TCPCommandPort 22179192, TID18) 
2015.11.06 05:21:01.399 WARNING:TCPCommandPort could not send event, TCP stream blocked (TCPCommandPort 22179193, TID18) 
2015.11.06 05:21:01.406 WARNING:TCPCommandPort could not send event, TCP stream blocked (TCPCommandPort 22179194, TID18)
Top
krambriw
Posts: 86
Joined: Sun Jan 04, 2015 8:48 am

Re: Problems running in a RPi

Post by krambriw »

Just to verify, I have now been running NetHome also in a Windows 7 box for a week or so. But, I insist, there is a problem with subscribing for events from the TCP port, it simply crashes after a week or so (maybe earlier if more events are sent, who knows). The log is completely flooded with messages like below.

Unfortunately I must declare that subscription connections to TCP ports currently does not work in the long run.

Code: Select all

2015.11.22 10:53:15.902 WARNING:TCPCommandPort could not send event, TCP stream blocked (TCPCommandPort 332672598, TID20) 
2015.11.22 10:53:15.902 WARNING:TCPCommandPort could not send event, TCP stream blocked (TCPCommandPort 332672599, TID20) 
2015.11.22 10:53:15.902 WARNING:TCPCommandPort could not send event, TCP stream blocked (TCPCommandPort 332672600, TID20) 
2015.11.22 10:53:15.902 WARNING:TCPCommandPort could not send event, TCP stream blocked (TCPCommandPort 332672601, TID20) 
2015.11.22 10:53:15.902 WARNING:TCPCommandPort could not send event, TCP stream blocked (TCPCommandPort 332672602, TID20) 
2015.11.22 10:53:15.902 WARNING:TCPCommandPort could not send event, TCP stream blocked (TCPCommandPort 332672603, TID20) 
2015.11.22 10:53:15.902 WARNING:TCPCommandPort could not send event, TCP stream blocked (TCPCommandPort 332672604, TID20) 
2015.11.22 10:53:15.902 WARNING:TCPCommandPort could not send event, TCP stream blocked (TCPCommandPort 332672605, TID20) 
2015.11.22 10:53:15.902 WARNING:TCPCommandPort could not send event, TCP stream blocked (TCPCommandPort 332672606, TID20) 
2015.11.22 10:53:15.902 WARNING:TCPCommandPort could not send event, TCP stream blocked (TCPCommandPort 332672607, TID20) 
2015.11.22 10:53:15.902 WARNING:TCPCommandPort could not send event, TCP stream blocked (TCPCommandPort 332672608, TID20) 
2015.11.22 10:53:15.912 WARNING:TCPCommandPort could not send event, TCP stream blocked (TCPCommandPort 332672609, TID20) 
2015.11.22 10:53:15.912 WARNING:TCPCommandPort could not send event, TCP stream blocked (TCPCommandPort 332672610, TID20) 
2015.11.22 10:53:15.912 WARNING:TCPCommandPort could not send event, TCP stream blocked (TCPCommandPort 332672611, TID20) 
2015.11.22 10:53:15.912 WARNING:TCPCommandPort could not send event, TCP stream blocked (TCPCommandPort 332672612, TID20) 
2015.11.22 10:53:15.912 WARNING:TCPCommandPort could not send event, TCP stream blocked (TCPCommandPort 332672613, TID20) 
2015.11.22 10:53:15.912 WARNING:TCPCommandPort could not send event, TCP stream blocked (TCPCommandPort 332672614, TID20) 
2015.11.22 10:53:15.912 WARNING:TCPCommandPort could not send event, TCP stream blocked (TCPCommandPort 332672615, TID20) 
2015.11.22 10:53:15.912 WARNING:TCPCommandPort could not send event, TCP stream blocked (TCPCommandPort 332672616, TID20) 
2015.11.22 10:53:15.912 WARNING:TCPCommandPort could not send event, TCP stream blocked (TCPCommandPort 332672617, TID20) 
2015.11.22 10:53:15.912 WARNING:TCPCommandPort could not send event, TCP stream blocked (TCPCommandPort 332672618, TID20) 
2015.11.22 10:53:15.912 WARNING:TCPCommandPort could not send event, TCP stream blocked (TCPCommandPort 332672619, TID20) 
2015.11.22 10:53:15.912 WARNING:TCPCommandPort could not send event, TCP stream blocked (TCPCommandPort 332672620, TID20) 
2015.11.22 10:53:15.912 WARNING:TCPCommandPort could not send event, TCP stream blocked (TCPCommandPort 332672621, TID20) 
2015.11.22 10:53:15.912 WARNING:TCPCommandPort could not send event, TCP stream blocked (TCPCommandPort 332672622, TID20) 
2015.11.22 10:53:15.912 WARNING:TCPCommandPort could not send event, TCP stream blocked (TCPCommandPort 332672623, TID20) 
2015.11.22 10:53:15.912 WARNING:TCPCommandPort could not send event, TCP stream blocked (TCPCommandPort 332672624, TID20) 
2015.11.22 10:53:15.912 WARNING:TCPCommandPort could not send event, TCP stream blocked (TCPCommandPort 332672625, TID20)
Top
stefangsbb
Site Admin
Posts: 313
Joined: Sun Nov 30, 2014 2:16 pm

Re: Problems running in a RPi

Post by stefangsbb »

Hmmm, it is kind of difficult to debug things that happens after a week, so there is no progress yet on this subject. It is also hard to know what the cause is - it could for example be the router that purges the open TCP-session after a week. Regardless, OpenNetHome should not go in to a state where it spams the log in this kind of situation so I will try to hunt it down... Until it is solved, maybe you could make your client restart the connection every 6:th day or something similar?
Top
krambriw
Posts: 86
Joined: Sun Jan 04, 2015 8:48 am

Re: Problems running in a RPi

Post by krambriw »

Until it is solved, maybe you could make your client restart the connection every 6:th day or something similar?
Unfortunately, what is needed is a restart of OpenNetHome, a new client connection cannot be made once the problem has started.
Top
Nasty76
Posts: 145
Joined: Tue Dec 09, 2014 1:20 am

Re: Problems running in a RPi

Post by Nasty76 »

Hmm if i remeber right i have some same kinda issues with tcp , so i use udp port to communicate and log spam not seeing anymore.
Top
krambriw
Posts: 86
Joined: Sun Jan 04, 2015 8:48 am

Re: Problems running in a RPi

Post by krambriw »

Yes but I have tried also udp port but no success when I try to subscribe to events (I have understood subscribing to events is only possible with tcp port)
Top
Post Reply

Return to “Software”