[Java] Spitting out stack traces without programmer's consent

[JavaLaurence]

Hi TF team,

 

Today I briefly disconnected the power to my stack, and discovered that my program spat out several stack traces without actually crashing my program.

 

java.net.SocketException: Host is down

at java.net.SocketOutputStream.socketWrite0(Native Method)

at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:109)

at java.net.SocketOutputStream.write(SocketOutputStream.java:141)

at com.tinkerforge.IPConnection.write(IPConnection.java:762)

at com.tinkerforge.Device.sendRequestExpectResponse(Device.java:192)

at com.tinkerforge.BrickletDistanceIR.getDistance(BrickletDistanceIR.java:224)

at com.softwarepearls.lego.hardware.tinkerforge.impl.tf.input.TFDistanceIR.getDistance(TFDistanceIR.java:89)

at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.dealWithWaterLevelAndPump(CellarWaterPumpController.java:203)

at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.controlLogic(CellarWaterPumpController.java:191)

at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.start(CellarWaterPumpController.java:174)

at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.main(CellarWaterPumpController.java:370)

 

Looking at how IPConnection is implemented, I can see lots of places where you code things like this:

 

try {

...;

} catch(java.io.IOException e) {

e.printStackTrace();

}

 

This is not very nice, and ignores several Java best practices.

 

Especially since the TinkerForge API has a NotConnectedException, doing the above doesn't make sense. My code is trying to catch the NotConnectedException, but instead it never arrives, and my System.out fills up with stack traces...

 

A much cleaner approach would be to code most of your try-catches as follows:

 

 

try {

...;

} catch(java.io.IOException e) {

throw new NotConnectedException(e); // retain root cause exception!

}

 

That way, the top-level application can decide to do what it wants with the exception (and the console stays clean).

 

In general, you also want to avoid all e.printStackTrace(); statements. Library components should never do this, as the application logic has no way of reacting to, nor suppressing, such events.

 

Finally, in the above scenario I'm doing a getDistance() on my DistanceIR ... but it happily returns some value (what value? the connection is down!), without throwing an exception. In my book, that's broken behavior.

 

HTH

 

  Laurence

 

[photron]

You're right regarding the try/catch/print in IPconnection.sendRequest(). This should be handled differently. But just throwing a NotConnectedException exception there is wrong, because socket is not null resulting in a AlreadyConnectedException being thrown if you call connect() in your NotConnectedException handler. This results in a situation where the exceptions contradict each other. The correct approach for this would be to handle a socket write error the same as a socket read error: Deal with it properly as a disconnect, trigger the disconnected callback and the auto-reconnect handling, if enabled.

 

I think for the try/catch/print in disconnect() where we just want to close the streams and socket we should not raise an additional exception, but just ignore any IOException on the way out closing the connection.

 

Almost all remaining try/catch/print's are on internal threads, where it doesn't make sense to throw them wrap in another exception, because that will just kill the thread breaking the internal working of the IPConnection. Also most of them are InterruptedExceptions that should never be able to occur, except someone decides to fiddle with the internals of the IPConnection and call interrupt() on the internal threads. So we need to catch and ignore InterruptedExceptions there.

 

Finally, your getDistance() won't return you a value in case IPconnection.sendRequest() fails the way you've described, because without a request being send there won't be any response and Device.sendRequest() will raise a TimeoutException.

[remotecontrol]

I also though about a better way for the exception handling, because within the Android App a "printStackTrace()" is more or less lost. Currently I redirect stdout/stderr for testing onto the SD-Card, but I'm not satisfied with that solution.

 

One idea was to use something similar like Thread.setDefaultUncaughtExceptionHandler().

 

• the Tinkerforge API might offer something like IPConnection.setDefaultUncaughtExceptionHandler()
  
• This exception handler is populated as a callback by the Tinkerforge-implementation into every thread which is created by the API.
  
• within the catch-block the handler is called
  
• there is a default handler defined in the API, which is active by default, which just calls e.printStacktrace()
  
• It would be possible to have slightly different parameters in this exception handler, for example an enumeration value which gives information about the source of error. It would be easy for a client-application to react to the situation and either just log and continue or terminate the application.
  
• then the client application at least has a good chance to react of the exception if a way it is suitable for that kind of application
  

The change in the API is not complicated and doesn't affect existing applications. If you think this might be helpful I can make an implementation and send it to you.

[JavaLaurence]

Photron: you write "Finally, your getDistance() won't return you a value in case IPconnection.sendRequest() fails the way you've described, because without a request being send there won't be any response and Device.sendRequest() will raise a TimeoutException."

 

.. but I don't see any TimeoutException, and getDistance() does return happily. That's the point. getDistance() does return .. with a broken connection.

[photron]

remotecontrol, I think that's a reasonable idea. We could extend this to report exceptions from user code that might occur on the callback thread will executing user callback functions as well. AuronX suggested something similar for exceptions in user callback function in the C# bindings last week, but I didn't decide on a final solution for this yet.

[photron]

.. but I don't see any TimeoutException, and getDistance() does return happily. That's the point. getDistance() does return .. with a broken connection.

 

I could not reproduce your exact problem. For me the socket read call in the receive thread is the one that detects the disconnect, never the socket write in IPConnection.sendRequest() as in your case. I also get the TimeoutExceptions as expected in this case.

 

Can you reproduce this problem? What is the order of events in that case? Are you calling getDistance() in a loop, see the stack trace print from the SocketException about "Host is down" and after that a getDistance() call returns you a value? Does that value look valid?

 

If that's the case is there only one successful getDistance() call after the stack trace and all following calls fail with a TimeoutException? Or does getDistance() just work for several calls in a row after the stack trace?

[JavaLaurence]

getDistance() just keeps "working", like the Duracell bunny ;-)

 

I'll give you the code so that you can follow the logic, but first, dinner calls... back later.

 

  L.

[JavaLaurence]

I've attached the code of my main class, and the Distance IR wrapper class.. and here's a dump of System.out showing the stack traces, but no actual program crash.. the program keeps going.

 

Starting Cellar Water Pump Control System @ Fri Feb 22 22:23:25 CET 2013

Running on Java 1.7.0_04 hosted by Mac OS X 10.7.5

Initializing TinkerForge stack.. Done.

Switching pump ON @ Fri Feb 22 23:10:32 CET 2013. Safety OFF override! Duration: 00:00:45

Switching pump ON @ Fri Feb 22 23:54:04 CET 2013. Duration: 00:00:25

Switching pump ON @ Fri Feb 22 23:54:34 CET 2013. Duration: 00:00:10

Switching pump ON @ Sat Feb 23 00:53:27 CET 2013. Duration: 00:00:23

Switching pump ON @ Sat Feb 23 01:50:05 CET 2013. Safety OFF override! Duration: 00:00:45

Switching pump ON @ Sat Feb 23 02:51:07 CET 2013. Duration: 00:00:16

Switching pump ON @ Sat Feb 23 03:38:46 CET 2013. Safety OFF override! Duration: 00:00:45

Switching pump ON @ Sat Feb 23 04:43:43 CET 2013. Safety OFF override! Duration: 00:00:45

Switching pump ON @ Sat Feb 23 05:44:50 CET 2013. Duration: 00:00:26

Switching pump ON @ Sat Feb 23 05:45:19 CET 2013. Duration: 00:00:03

Switching pump ON @ Sat Feb 23 06:38:05 CET 2013. Duration: 00:00:23

Switching pump ON @ Sat Feb 23 07:24:31 CET 2013. Duration: 00:00:13

Switching pump ON @ Sat Feb 23 07:45:16 CET 2013. Safety OFF override! Duration: 00:00:45

Switching pump ON @ Sat Feb 23 08:37:04 CET 2013. Duration: 00:00:22

Switching pump ON @ Sat Feb 23 09:26:04 CET 2013. Duration: 00:00:16

Switching pump ON @ Sat Feb 23 10:21:25 CET 2013. Duration: 00:00:28

Switching pump ON @ Sat Feb 23 11:19:28 CET 2013. Duration: 00:00:24

Switching pump ON @ Sat Feb 23 12:18:00 CET 2013. Duration: 00:00:18

Switching pump ON @ Sat Feb 23 12:18:20 CET 2013. Safety OFF override! Duration: 00:00:45

Switching pump ON @ Sat Feb 23 13:15:43 CET 2013. Duration: 00:00:23

Switching pump ON @ Sat Feb 23 14:12:30 CET 2013. Duration: 00:00:17

Switching pump ON @ Sat Feb 23 15:00:19 CET 2013. Safety OFF override! Duration: 00:00:45

java.net.SocketException: Host is down

at java.net.SocketOutputStream.socketWrite0(Native Method)

at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:109)

at java.net.SocketOutputStream.write(SocketOutputStream.java:141)

at com.tinkerforge.IPConnection.sendRequest(IPConnection.java:817)

at com.tinkerforge.Device.sendRequest(Device.java:185)

at com.tinkerforge.BrickletDistanceIR.getDistance(BrickletDistanceIR.java:219)

at com.softwarepearls.lego.hardware.tinkerforge.impl.tf.input.TFDistanceIR.getDistance(TFDistanceIR.java:56)

at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.dealWithWaterLevelAndPump(CellarWaterPumpController.java:209)

at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.controlLogic(CellarWaterPumpController.java:197)

at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.start(CellarWaterPumpController.java:181)

at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.main(CellarWaterPumpController.java:418)

java.net.SocketException: Host is down

at java.net.SocketOutputStream.socketWrite0(Native Method)

at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:109)

at java.net.SocketOutputStream.write(SocketOutputStream.java:141)

at com.tinkerforge.IPConnection.sendRequest(IPConnection.java:817)

at com.tinkerforge.Device.sendRequest(Device.java:185)

at com.tinkerforge.BrickletDistanceIR.getDistance(BrickletDistanceIR.java:219)

at com.softwarepearls.lego.hardware.tinkerforge.impl.tf.input.TFDistanceIR.getDistance(TFDistanceIR.java:56)

at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.dealWithWaterLevelAndPump(CellarWaterPumpController.java:209)

at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.controlLogic(CellarWaterPumpController.java:197)

at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.start(CellarWaterPumpController.java:181)

at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.main(CellarWaterPumpController.java:418)

java.net.SocketException: Host is down

at java.net.SocketOutputStream.socketWrite0(Native Method)

at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:109)

at java.net.SocketOutputStream.write(SocketOutputStream.java:141)

at com.tinkerforge.IPConnection.sendRequest(IPConnection.java:817)

at com.tinkerforge.Device.sendRequest(Device.java:185)

at com.tinkerforge.BrickletDistanceIR.getDistance(BrickletDistanceIR.java:219)

at com.softwarepearls.lego.hardware.tinkerforge.impl.tf.input.TFDistanceIR.getDistance(TFDistanceIR.java:56)

at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.dealWithWaterLevelAndPump(CellarWaterPumpController.java:209)

at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.controlLogic(CellarWaterPumpController.java:197)

at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.start(CellarWaterPumpController.java:181)

at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.main(CellarWaterPumpController.java:418)

java.net.SocketException: Host is down

at java.net.SocketOutputStream.socketWrite0(Native Method)

at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:109)

at java.net.SocketOutputStream.write(SocketOutputStream.java:141)

at com.tinkerforge.IPConnection.sendRequest(IPConnection.java:817)

at com.tinkerforge.Device.sendRequest(Device.java:185)

at com.tinkerforge.BrickletDistanceIR.getDistance(BrickletDistanceIR.java:219)

at com.softwarepearls.lego.hardware.tinkerforge.impl.tf.input.TFDistanceIR.getDistance(TFDistanceIR.java:56)

at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.dealWithWaterLevelAndPump(CellarWaterPumpController.java:209)

at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.controlLogic(CellarWaterPumpController.java:197)

at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.start(CellarWaterPumpController.java:181)

at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.main(CellarWaterPumpController.java:418)

java.net.SocketException: Host is down

at java.net.SocketOutputStream.socketWrite0(Native Method)

at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:109)

at java.net.SocketOutputStream.write(SocketOutputStream.java:141)

at com.tinkerforge.IPConnection.sendRequest(IPConnection.java:817)

at com.tinkerforge.Device.sendRequest(Device.java:185)

at com.tinkerforge.BrickletDistanceIR.getDistance(BrickletDistanceIR.java:219)

at com.softwarepearls.lego.hardware.tinkerforge.impl.tf.input.TFDistanceIR.getDistance(TFDistanceIR.java:56)

at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.dealWithWaterLevelAndPump(CellarWaterPumpController.java:209)

at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.controlLogic(CellarWaterPumpController.java:197)

at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.start(CellarWaterPumpController.java:181)

at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.main(CellarWaterPumpController.java:418)

java.net.SocketException: Host is down

at java.net.SocketOutputStream.socketWrite0(Native Method)

at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:109)

at java.net.SocketOutputStream.write(SocketOutputStream.java:141)

at com.tinkerforge.IPConnection.sendRequest(IPConnection.java:817)

at com.tinkerforge.Device.sendRequest(Device.java:185)

at com.tinkerforge.BrickletDistanceIR.getDistance(BrickletDistanceIR.java:219)

at com.softwarepearls.lego.hardware.tinkerforge.impl.tf.input.TFDistanceIR.getDistance(TFDistanceIR.java:56)

at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.dealWithWaterLevelAndPump(CellarWaterPumpController.java:209)

at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.controlLogic(CellarWaterPumpController.java:197)

at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.start(CellarWaterPumpController.java:181)

at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.main(CellarWaterPumpController.java:418)

CellarWaterPumpController.java

TFDistanceIR.java

[photron]

I don't see any general problem within your attached code.

 

I stripped down your code to get a working program. The stripped down version is attached.

 

My test stack: Step-Down Power Supply, Master Brick, WIFI Extension, Dual Relay Bricklet, Temperatur Bricklet, Distance IR Bricklet, LCD 20x4 Bricket. WIFI connection established using a AVM FritzBox 7170.

 

The program works as expected. It prints on the LCD and operates the pump. Then I disconnect the power input from the Step-Down Power Supply and the GetDistance() call throws a TimeoutException. Then I power up the stack again. After ~20sec the WIFI Extension re-established the connection, the IPConnection auto-reconnects, and GetDistance() works again.

 

$ java -cp Tinkerforge.jar:. CellarWaterPumpController_Test1
Starting Cellar Water Pump Control System @ Mon Feb 25 13:53:26 CET 2013
Initializing TinkerForge stack..
CONNECTED 0
FAKE: lcd.setCustomCharacter
[...]
FAKE: lcd.setCustomCharacter
Done.
LOG: Mon Feb 25 13:53:26 CET 2013: Polling sensors... 
LOG: Mon Feb 25 13:53:26 CET 2013: Water Distance = 67.1 cm
LOG: Mon Feb 25 13:53:26 CET 2013: Water level is low.
[...]
LOG: Mon Feb 25 13:53:28 CET 2013: Polling sensors... 
LOG: Mon Feb 25 13:53:28 CET 2013: Water Distance = 61.0 cm
LOG: Mon Feb 25 13:53:28 CET 2013: Water level is low.
LOG: Mon Feb 25 13:53:29 CET 2013: Polling sensors... 
LOG: Mon Feb 25 13:53:29 CET 2013: Water Distance = 7.0 cm
LOG: Mon Feb 25 13:53:29 CET 2013: Water level is high.
Switching pump ON @ Mon Feb 25 13:53:29 CET 2013. 
FAKE: setPumpState ON
LOG: Mon Feb 25 13:53:29 CET 2013: Polling sensors... 
LOG: Mon Feb 25 13:53:29 CET 2013: Water Distance = 7.0 cm
LOG: Mon Feb 25 13:53:29 CET 2013: Water level is high.
LOG: Mon Feb 25 13:53:30 CET 2013: Polling sensors... 
LOG: Mon Feb 25 13:53:30 CET 2013: Water Distance = 61.0 cm
LOG: Mon Feb 25 13:53:30 CET 2013: Water level is low.
Duration: 1092
FAKE: setPumpState OFF
LOG: Mon Feb 25 13:53:30 CET 2013: Polling sensors... 
LOG: Mon Feb 25 13:53:30 CET 2013: Water Distance = 61.0 cm
LOG: Mon Feb 25 13:53:30 CET 2013: Water level is low.
[...]
LOG: Mon Feb 25 13:53:34 CET 2013: Polling sensors... 
LOG: Mon Feb 25 13:53:34 CET 2013: Water Distance = 67.1 cm
LOG: Mon Feb 25 13:53:34 CET 2013: Water level is low.

[Disconnecting the input of the Step-Down Power Supply for 3sec]

LOG: Mon Feb 25 13:53:34 CET 2013: Polling sensors... 
LOG: Mon Feb 25 13:53:37 CET 2013: Ooops: Did not receive response in time for function ID 1
[...]
LOG: Mon Feb 25 13:53:52 CET 2013: Polling sensors... 
LOG: Mon Feb 25 13:53:54 CET 2013: Ooops: Did not receive response in time for function ID 1
LOG: Mon Feb 25 13:53:54 CET 2013: Polling sensors... 

[WIFI Extension re-established connection, IPConnections auto-reconnects]

DISCONNECTED 1
CONNECTED 1
LOG: Mon Feb 25 13:53:57 CET 2013: Ooops: Did not receive response in time for function ID 1
LOG: Mon Feb 25 13:53:57 CET 2013: Polling sensors... 
LOG: Mon Feb 25 13:53:57 CET 2013: Water Distance = 67.1 cm
LOG: Mon Feb 25 13:53:57 CET 2013: Water level is low.
[...]
LOG: Mon Feb 25 13:53:59 CET 2013: Polling sensors... 
LOG: Mon Feb 25 13:53:59 CET 2013: Water Distance = 61.0 cm
LOG: Mon Feb 25 13:53:59 CET 2013: Water level is low.
LOG: Mon Feb 25 13:54:00 CET 2013: Polling sensors... 
LOG: Mon Feb 25 13:54:00 CET 2013: Water Distance = 7.0 cm
LOG: Mon Feb 25 13:54:00 CET 2013: Water level is high.
Switching pump ON @ Mon Feb 25 13:54:00 CET 2013. 
FAKE: setPumpState ON
LOG: Mon Feb 25 13:54:00 CET 2013: Polling sensors... 
LOG: Mon Feb 25 13:54:00 CET 2013: Water Distance = 61.0 cm
LOG: Mon Feb 25 13:54:00 CET 2013: Water level is low.
Duration: 543
FAKE: setPumpState OFF
LOG: Mon Feb 25 13:54:01 CET 2013: Polling sensors... 
LOG: Mon Feb 25 13:54:01 CET 2013: Water Distance = 61.0 cm
LOG: Mon Feb 25 13:54:01 CET 2013: Water level is low.
[...]
LOG: Mon Feb 25 13:54:04 CET 2013: Polling sensors... 
LOG: Mon Feb 25 13:54:04 CET 2013: Water Distance = 61.0 cm
LOG: Mon Feb 25 13:54:04 CET 2013: Water level is low.
^CFAKE: reset

 

So basically I still cannot reproduce your problem. I don't get the SocketException for "Host is down" in sendRequest() but I get the TimeoutException as expected.

 

This was tested with Oracle Java 1.7.0 and OpenJDK 1.6.0_27 on Linux, and Java 1.6.0_37 on Mac OS X. All working, but I don't expect the Java version to blame here

 

Java Bindings version 2.0.5 were used.

 

Can you reproduce the problem with my stripped down version, or the simple example I attached?

CellarWaterPumpController_Test1.java

ExampleSimple.java

[JavaLaurence]

OK. will test this later today. Just another data point: looking at my program's log from the past night, the connection again got lost, and again the program keeps going without any TimoutExceptions.

 

And here's a clue: I had brickv running all night too.. and it ALSO shows zero (0) timeouts.

 

So something's going on, definitely.

[photron]

Does the connection loss occur spontaneous, or do you have to do something to trigger this? You said it occurred as you disconnected the stack power input for a moment.

 

Depending on the tab you look at you might not see timeouts immediately. For example, the Distance IR Bricklet tab is callback based. After the initialization it doesn't call any getters or setters anymore.

 

If you switch between tabs you should be able to see the timeout counters go up, as the initialization is re-executed when you switch to a tab.

[JavaLaurence]

Photron, mea culpa 

 

Found the TimeoutException-swallowing bug in my code, not yours.

 

Also the 0 timeouts in brickv is due to the behavior you just explained.. nothing more sinister.

 

I'll hopefully compensate your loss of time by ordering some more TF kit to play with. ;-)

 

  L.

[photron]

Nice, now I can stop wondering why the TimeoutException got lost

[JavaLaurence]

Yes, sorry about that :-S a simple quick edit caused the bug on my side.

 

Now the output is more like this:

 

Switching pump ON @ Wed Feb 27 01:23:09 CET 2013. Duration: 00:00:16

Switching pump ON @ Wed Feb 27 02:17:32 CET 2013. Duration: 00:00:18

Switching pump ON @ Wed Feb 27 02:45:23 CET 2013. Duration: 00:00:21

Switching pump ON @ Wed Feb 27 02:45:47 CET 2013. Duration: 00:00:04

Switching pump ON @ Wed Feb 27 02:45:55 CET 2013. Duration: 00:00:01

Switching pump ON @ Wed Feb 27 02:46:03 CET 2013. Duration: 00:00:04

com.tinkerforge.TimeoutException: Did not receive response in time for function ID 1

at com.tinkerforge.Device.sendRequest(Device.java:197)

at com.tinkerforge.BrickletDistanceIR.getDistance(BrickletDistanceIR.java:219)

at com.softwarepearls.lego.hardware.tinkerforge.impl.tf.input.TFDistanceIR.getDistance(TFDistanceIR.java:56)

at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.dealWithWaterLevelAndPump(CellarWaterPumpController.java:209)

at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.controlLogic(CellarWaterPumpController.java:197)

at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.start(CellarWaterPumpController.java:181)

at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.main(CellarWaterPumpController.java:418)

com.tinkerforge.TimeoutException: Did not receive response in time for function ID 1

at com.tinkerforge.Device.sendRequest(Device.java:197)

at com.tinkerforge.BrickletDistanceIR.getDistance(BrickletDistanceIR.java:219)

at com.softwarepearls.lego.hardware.tinkerforge.impl.tf.input.TFDistanceIR.getDistance(TFDistanceIR.java:56)

at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.dealWithWaterLevelAndPump(CellarWaterPumpController.java:209)

at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.controlLogic(CellarWaterPumpController.java:197)

at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.start(CellarWaterPumpController.java:181)

at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.main(CellarWaterPumpController.java:418)

Switching pump ON @ Wed Feb 27 03:56:25 CET 2013. Duration: 00:00:39

Switching pump ON @ Wed Feb 27 04:36:35 CET 2013. Duration: 00:00:25

Switching pump ON @ Wed Feb 27 05:25:56 CET 2013. Duration: 00:00:15

Switching pump ON @ Wed Feb 27 05:50:32 CET 2013. Duration: 00:00:20

com.tinkerforge.TimeoutException: Did not receive response in time for function ID 1

at com.tinkerforge.Device.sendRequest(Device.java:197)

at com.tinkerforge.BrickletDistanceIR.getDistance(BrickletDistanceIR.java:219)

at com.softwarepearls.lego.hardware.tinkerforge.impl.tf.input.TFDistanceIR.getDistance(TFDistanceIR.java:56)

at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.dealWithWaterLevelAndPump(CellarWaterPumpController.java:209)

at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.controlLogic(CellarWaterPumpController.java:197)

at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.start(CellarWaterPumpController.java:181)

at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.main(CellarWaterPumpController.java:418)

Switching pump ON @ Wed Feb 27 07:13:50 CET 2013. Duration: 00:00:18

Switching pump ON @ Wed Feb 27 07:38:05 CET 2013. Duration: 00:00:20

Switching pump ON @ Wed Feb 27 08:31:43 CET 2013. Duration: 00:00:24

com.tinkerforge.TimeoutException: Did not receive response in time for function ID 1

at com.tinkerforge.Device.sendRequest(Device.java:197)

at com.tinkerforge.BrickletDistanceIR.getDistance(BrickletDistanceIR.java:219)

at com.softwarepearls.lego.hardware.tinkerforge.impl.tf.input.TFDistanceIR.getDistance(TFDistanceIR.java:56)

at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.dealWithWaterLevelAndPump(CellarWaterPumpController.java:209)

at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.controlLogic(CellarWaterPumpController.java:197)

at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.start(CellarWaterPumpController.java:181)

at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.main(CellarWaterPumpController.java:418)

Switching pump ON @ Wed Feb 27 09:20:20 CET 2013. Duration: 00:00:15

[photron]

Does this log tell that it works in general, but that there are some spontaneous TimeoutExceptions in between? I assume you're still calling getDistance() every 500ms.

 

This might be due to WIFI reconnects. You could add the IPConnection ConnectedListener and DisconnectedListener to be able to log automatic reconnects of the IP Connection.

 

Did you have a look at the logs of you WIFI access point? Are there any reconnects from the WIFI Extension at the time the TimeoutException occur? Maybe there was a reconnect just in the middle of a getter call.

 

You could also log the time at which a TimeoutException occurs. For example, are the first two TimeoutExceptions from two getDistance() calls in a row, or are the minutes apart?

[JavaLaurence]

I've changed the program to adopt your two suggestions (listeners + timestamps on TimeoutException). Let's see what the log contains tomorrow morning ;-)

 

BTW, have a look at what I have to do in the listener code to be able to report a human readable reason instead of meaningless short? Not pretty.. any chance of TinkerForge adopting enums for stuff like this? They've been around for a long time in Java..

 

@Override
public void disconnected(final short disconnectReason) {

	System.err.println("\nHmm. Disconnected @ " + currentTime() + " because: "
			+ ReflectionKit.getNameOfShortConstant(IPConnection.class, "DISCONNECT_REASON_", disconnectReason));
}

@Override
public void connected(final short connectReason) {

	System.out.println("\nAha. Connected @ " + currentTime() + " because: "
			+ ReflectionKit.getNameOfShortConstant(IPConnection.class, "CONNECT_REASON_", connectReason));
}


public static String getNameOfShortConstant(final Class<?> declaringClass, final String symbolicConstantPrefix, final short constantValue) {

	return getNameOfNumericConstant(declaringClass, short.class, symbolicConstantPrefix, constantValue);
}

/*************************************************************************
 * Get the name of symbolic constant as defined in some class. This method
 * scans the list of fields of a class to find a constant that has the same
 * value as the argument. <br>
 * Here are some examples:
 * <ul>
 * <LI>getNameOfIntConstant(0, Cursor.class) -> "DEFAULT_CURSOR"
 * <LI>
 * getNameOfIntConstant(3, Cursor.class) -> "WAIT_CURSOR"
 * </ul>
 * 
 * @param constantValue the value of the integer constant for which we want
 * to find the symbolic name
 * @param declaringClass the class in which the constant is declared
 * @param symbolicConstantPrefix a String prefix that the symbolic constant
 * must have
 * @return the name of the constant, or null if no such constant found.
 *************************************************************************/
public static <N extends Number> String getNameOfNumericConstant(final Class<?> declaringClass, final Class<N> numberClass,
		final String symbolicConstantPrefix, final N constantValue) {

	final Field[] fields = declaringClass.getFields();

	final Long constantAsLong = constantValue.longValue();
	for (final Field field : fields) {
		if (field.getType() == numberClass) {
			if (field.getName().startsWith(symbolicConstantPrefix)) {
				try {
					final Long value = field.getLong(null);
					if (value.equals(constantAsLong)) {
						return field.getName();
					}
				}
				catch (final IllegalArgumentException illegalArgumentException) {
					:
				}
				catch (final IllegalAccessException illegalAccessException) {
				:
				}
			}
		}
	} // end forall fields

	return null;
}

[JavaLaurence]

Here's the log of past night. I'll see later if I can correlate any exceptions with stuff happening in AP.

 

Starting Cellar Water Pump Control System @ Wed Feb 27 22:38:51 CET 2013 Running on Java 1.7.0_04 hosted by Mac OS X 10.7.5 Initializing TinkerForge stack.. Aha. Connected @ 21:38:51 because: CONNECT_REASON_REQUEST Done. [1] Ouch.. exception @ Wed Feb 27 22:39:22 CET 2013 com.tinkerforge.TimeoutException: Did not receive response in time for function ID 1 at com.tinkerforge.Device.sendRequest(Device.java:197) at com.tinkerforge.BrickletTemperature.getTemperature(BrickletTemperature.java:139) at com.softwarepearls.lego.hardware.tinkerforge.impl.tf.input.TFTemperature.getTemperature(TFTemperature.java:53) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.dealWithWaterLevelAndPump(CellarWaterPumpController.java:225) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.controlLogic(CellarWaterPumpController.java:211) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.start(CellarWaterPumpController.java:192) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.main(CellarWaterPumpController.java:446) [2] Ouch.. exception @ Wed Feb 27 22:39:57 CET 2013 com.tinkerforge.TimeoutException: Did not receive response in time for function ID 1 at com.tinkerforge.Device.sendRequest(Device.java:197) at com.tinkerforge.BrickletDistanceIR.getDistance(BrickletDistanceIR.java:219) at com.softwarepearls.lego.hardware.tinkerforge.impl.tf.input.TFDistanceIR.getDistance(TFDistanceIR.java:56) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.dealWithWaterLevelAndPump(CellarWaterPumpController.java:223) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.controlLogic(CellarWaterPumpController.java:211) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.start(CellarWaterPumpController.java:192) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.main(CellarWaterPumpController.java:446) Switching pump ON @ Wed Feb 27 22:41:16 CET 2013. Duration: 00:00:24 Switching pump ON @ Wed Feb 27 22:41:43 CET 2013. Duration: 00:00:01 com.tinkerforge.TimeoutException: Did not receive response in time for function ID 2 at com.tinkerforge.Device.sendRequest(Device.java:197) at com.tinkerforge.BrickletDualRelay.getState(BrickletDualRelay.java:126) at com.softwarepearls.lego.hardware.tinkerforge.impl.tf.output.TFDualRelay.getState(TFDualRelay.java:43) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.external.Pump.getPumpState(Pump.java:46) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.showStatus(CellarWaterPumpController.java:295) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.updateLCD(CellarWaterPumpController.java:249) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.controlLogic(CellarWaterPumpController.java:213) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.start(CellarWaterPumpController.java:192) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.main(CellarWaterPumpController.java:446) [3] Ouch.. exception @ Wed Feb 27 22:48:27 CET 2013 com.tinkerforge.TimeoutException: Did not receive response in time for function ID 1 at com.tinkerforge.Device.sendRequest(Device.java:197) at com.tinkerforge.BrickletDistanceIR.getDistance(BrickletDistanceIR.java:219) at com.softwarepearls.lego.hardware.tinkerforge.impl.tf.input.TFDistanceIR.getDistance(TFDistanceIR.java:56) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.dealWithWaterLevelAndPump(CellarWaterPumpController.java:223) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.controlLogic(CellarWaterPumpController.java:211) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.start(CellarWaterPumpController.java:192) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.main(CellarWaterPumpController.java:446) [4] Ouch.. exception @ Wed Feb 27 22:53:22 CET 2013 com.tinkerforge.TimeoutException: Did not receive response in time for function ID 1 at com.tinkerforge.Device.sendRequest(Device.java:197) at com.tinkerforge.BrickletTemperature.getTemperature(BrickletTemperature.java:139) at com.softwarepearls.lego.hardware.tinkerforge.impl.tf.input.TFTemperature.getTemperature(TFTemperature.java:53) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.dealWithWaterLevelAndPump(CellarWaterPumpController.java:225) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.controlLogic(CellarWaterPumpController.java:211) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.start(CellarWaterPumpController.java:192) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.main(CellarWaterPumpController.java:446) [5] Ouch.. exception @ Wed Feb 27 22:53:25 CET 2013 com.tinkerforge.TimeoutException: Did not receive response in time for function ID 1 at com.tinkerforge.Device.sendRequest(Device.java:197) at com.tinkerforge.BrickletDistanceIR.getDistance(BrickletDistanceIR.java:219) at com.softwarepearls.lego.hardware.tinkerforge.impl.tf.input.TFDistanceIR.getDistance(TFDistanceIR.java:56) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.dealWithWaterLevelAndPump(CellarWaterPumpController.java:223) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.controlLogic(CellarWaterPumpController.java:211) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.start(CellarWaterPumpController.java:192) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.main(CellarWaterPumpController.java:446) [6] Ouch.. exception @ Wed Feb 27 22:53:27 CET 2013 com.tinkerforge.TimeoutException: Did not receive response in time for function ID 1 at com.tinkerforge.Device.sendRequest(Device.java:197) at com.tinkerforge.BrickletDistanceIR.getDistance(BrickletDistanceIR.java:219) at com.softwarepearls.lego.hardware.tinkerforge.impl.tf.input.TFDistanceIR.getDistance(TFDistanceIR.java:56) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.dealWithWaterLevelAndPump(CellarWaterPumpController.java:223) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.controlLogic(CellarWaterPumpController.java:211) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.start(CellarWaterPumpController.java:192) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.main(CellarWaterPumpController.java:446) [7] Ouch.. exception @ Wed Feb 27 22:53:30 CET 2013 com.tinkerforge.TimeoutException: Did not receive response in time for function ID 1 at com.tinkerforge.Device.sendRequest(Device.java:197) at com.tinkerforge.BrickletDistanceIR.getDistance(BrickletDistanceIR.java:219) at com.softwarepearls.lego.hardware.tinkerforge.impl.tf.input.TFDistanceIR.getDistance(TFDistanceIR.java:56) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.dealWithWaterLevelAndPump(CellarWaterPumpController.java:223) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.controlLogic(CellarWaterPumpController.java:211) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.start(CellarWaterPumpController.java:192) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.main(CellarWaterPumpController.java:446) [8] Ouch.. exception @ Wed Feb 27 22:53:32 CET 2013 com.tinkerforge.TimeoutException: Did not receive response in time for function ID 1 at com.tinkerforge.Device.sendRequest(Device.java:197) at com.tinkerforge.BrickletDistanceIR.getDistance(BrickletDistanceIR.java:219) at com.softwarepearls.lego.hardware.tinkerforge.impl.tf.input.TFDistanceIR.getDistance(TFDistanceIR.java:56) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.dealWithWaterLevelAndPump(CellarWaterPumpController.java:223) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.controlLogic(CellarWaterPumpController.java:211) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.start(CellarWaterPumpController.java:192) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.main(CellarWaterPumpController.java:446) [9] Ouch.. exception @ Wed Feb 27 22:53:35 CET 2013 com.tinkerforge.TimeoutException: Did not receive response in time for function ID 1 at com.tinkerforge.Device.sendRequest(Device.java:197) at com.tinkerforge.BrickletDistanceIR.getDistance(BrickletDistanceIR.java:219) at com.softwarepearls.lego.hardware.tinkerforge.impl.tf.input.TFDistanceIR.getDistance(TFDistanceIR.java:56) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.dealWithWaterLevelAndPump(CellarWaterPumpController.java:223) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.controlLogic(CellarWaterPumpController.java:211) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.start(CellarWaterPumpController.java:192) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.main(CellarWaterPumpController.java:446) [10] Ouch.. exception @ Wed Feb 27 22:53:37 CET 2013 com.tinkerforge.TimeoutException: Did not receive response in time for function ID 1 at com.tinkerforge.Device.sendRequest(Device.java:197) at com.tinkerforge.BrickletDistanceIR.getDistance(BrickletDistanceIR.java:219) at com.softwarepearls.lego.hardware.tinkerforge.impl.tf.input.TFDistanceIR.getDistance(TFDistanceIR.java:56) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.dealWithWaterLevelAndPump(CellarWaterPumpController.java:223) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.controlLogic(CellarWaterPumpController.java:211) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.start(CellarWaterPumpController.java:192) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.main(CellarWaterPumpController.java:446) [11] Ouch.. exception @ Wed Feb 27 22:53:40 CET 2013 com.tinkerforge.TimeoutException: Did not receive response in time for function ID 1 at com.tinkerforge.Device.sendRequest(Device.java:197) at com.tinkerforge.BrickletDistanceIR.getDistance(BrickletDistanceIR.java:219) at com.softwarepearls.lego.hardware.tinkerforge.impl.tf.input.TFDistanceIR.getDistance(TFDistanceIR.java:56) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.dealWithWaterLevelAndPump(CellarWaterPumpController.java:223) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.controlLogic(CellarWaterPumpController.java:211) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.start(CellarWaterPumpController.java:192) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.main(CellarWaterPumpController.java:446) [12] Ouch.. exception @ Wed Feb 27 22:53:42 CET 2013 com.tinkerforge.TimeoutException: Did not receive response in time for function ID 1 at com.tinkerforge.Device.sendRequest(Device.java:197) at com.tinkerforge.BrickletDistanceIR.getDistance(BrickletDistanceIR.java:219) at com.softwarepearls.lego.hardware.tinkerforge.impl.tf.input.TFDistanceIR.getDistance(TFDistanceIR.java:56) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.dealWithWaterLevelAndPump(CellarWaterPumpController.java:223) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.controlLogic(CellarWaterPumpController.java:211) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.start(CellarWaterPumpController.java:192) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.main(CellarWaterPumpController.java:446) Hmm. Disconnected @ 21:53:42 because: DISCONNECT_REASON_ERROR Aha. Connected @ 21:53:42 because: CONNECT_REASON_AUTO_RECONNECT [13] Ouch.. exception @ Wed Feb 27 22:53:45 CET 2013 com.tinkerforge.TimeoutException: Did not receive response in time for function ID 1 at com.tinkerforge.Device.sendRequest(Device.java:197) at com.tinkerforge.BrickletDistanceIR.getDistance(BrickletDistanceIR.java:219) at com.softwarepearls.lego.hardware.tinkerforge.impl.tf.input.TFDistanceIR.getDistance(TFDistanceIR.java:56) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.dealWithWaterLevelAndPump(CellarWaterPumpController.java:223) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.controlLogic(CellarWaterPumpController.java:211) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.start(CellarWaterPumpController.java:192) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.main(CellarWaterPumpController.java:446) [14] Ouch.. exception @ Wed Feb 27 23:25:44 CET 2013 com.tinkerforge.TimeoutException: Did not receive response in time for function ID 1 at com.tinkerforge.Device.sendRequest(Device.java:197) at com.tinkerforge.BrickletDistanceIR.getDistance(BrickletDistanceIR.java:219) at com.softwarepearls.lego.hardware.tinkerforge.impl.tf.input.TFDistanceIR.getDistance(TFDistanceIR.java:56) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.dealWithWaterLevelAndPump(CellarWaterPumpController.java:223) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.controlLogic(CellarWaterPumpController.java:211) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.start(CellarWaterPumpController.java:192) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.main(CellarWaterPumpController.java:446) Duration: 00:44:46 [15] Ouch.. exception @ Wed Feb 27 23:27:03 CET 2013 com.tinkerforge.TimeoutException: Did not receive response in time for function ID 1 at com.tinkerforge.Device.sendRequest(Device.java:197) at com.tinkerforge.BrickletDistanceIR.getDistance(BrickletDistanceIR.java:219) at com.softwarepearls.lego.hardware.tinkerforge.impl.tf.input.TFDistanceIR.getDistance(TFDistanceIR.java:56) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.dealWithWaterLevelAndPump(CellarWaterPumpController.java:223) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.controlLogic(CellarWaterPumpController.java:211) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.start(CellarWaterPumpController.java:192) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.main(CellarWaterPumpController.java:446) [16] Ouch.. exception @ Thu Feb 28 01:53:42 CET 2013 com.tinkerforge.TimeoutException: Did not receive response in time for function ID 1 at com.tinkerforge.Device.sendRequest(Device.java:197) at com.tinkerforge.BrickletDistanceIR.getDistance(BrickletDistanceIR.java:219) at com.softwarepearls.lego.hardware.tinkerforge.impl.tf.input.TFDistanceIR.getDistance(TFDistanceIR.java:56) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.dealWithWaterLevelAndPump(CellarWaterPumpController.java:223) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.controlLogic(CellarWaterPumpController.java:211) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.start(CellarWaterPumpController.java:192) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.main(CellarWaterPumpController.java:446) Switching pump ON @ Thu Feb 28 02:03:32 CET 2013. Duration: 00:00:18 Switching pump ON @ Thu Feb 28 03:12:44 CET 2013. Duration: 00:00:35 Switching pump ON @ Thu Feb 28 04:29:44 CET 2013. Safety OFF override! Duration: 00:00:45 Switching pump ON @ Thu Feb 28 05:54:22 CET 2013. Duration: 00:00:19 Switching pump ON @ Thu Feb 28 06:50:57 CET 2013. Duration: 00:00:19 Switching pump ON @ Thu Feb 28 07:39:13 CET 2013. Safety OFF override! Duration: 00:00:45 [17] Ouch.. exception @ Thu Feb 28 07:53:44 CET 2013 com.tinkerforge.TimeoutException: Did not receive response in time for function ID 1 at com.tinkerforge.Device.sendRequest(Device.java:197) at com.tinkerforge.BrickletDistanceIR.getDistance(BrickletDistanceIR.java:219) at com.softwarepearls.lego.hardware.tinkerforge.impl.tf.input.TFDistanceIR.getDistance(TFDistanceIR.java:56) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.dealWithWaterLevelAndPump(CellarWaterPumpController.java:223) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.controlLogic(CellarWaterPumpController.java:211) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.start(CellarWaterPumpController.java:192) at com.softwarepearls.apps.hardware.tinkerforge.waterpump.CellarWaterPumpController.main(CellarWaterPumpController.java:446) Switching pump ON @ Thu Feb 28 08:36:41 CET 2013. Duration: 00:00:36

[JavaLaurence]

OK, first I had to learn a bit of DHCP protocol ;-)

 

Then I analysed the log from my AP (see attached file).

 

What i think happens is this: my AP (which has very few config options) issues DHCP leases lasting only 3 hours. I have no clue whether this is reasonable or paranoid. Anyway, my three Wifi-connected devices (incl TinkerForge stack with Wifi Extension) are therefore forced to beg the AP for a new lease every 3 hours. The logs show that renewing may take a few seconds, just enough for my 2Hz polling loop to fail to "see" the stack for a few polls. Resulting in Timeouts.

 

I know I should be using callbacks instead of polling, but for now, I'm perfectly happy with how things work. I'll see if there's any way to increase the lease time on my Belgacom BBox2 AP (a really crappy piece of kit).

DHCP.1.log

[photron]

That's interesting. I didn't expect that DHCP would be the cause for this timeouts. Good to know!

 

 

[JavaLaurence]

The DHCP lease times are not configurable on my AP (which is a standard issue residential box from Belgium's 2nd-largest ISP, Belgacom). But you can set them to "static", so I've now made the Wifi Extension get a static IP address.. so let's see if this fixes these awkward TimeoutExceptions.