Posts Tagged ‘ZK’

The ZK AJAX Library ignores some of the user’s input

February 1, 2009

I have used ZK for a while, building mostly web administrative interfaces. My applications get usually used in the intranet, they rarely get exposure with the open Internet. The distance between the server and the browser is usually a few routers, so they benefit of an especially low latency and wide bandwidth.

Many users reported that sometimes the application fails to perform the instructed task. From time to time, nothing happens when the user pushes a button or chooses an item from a context menu. Although I have first suspected a programming error, the random distribution of this behavior, in various applications, determined me to suspect the ZK engine of this loss of events.

I have designed a simple test application to check this issue:

<window xmlns="http://www.zkoss.org/2005/zul" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
    xsi:schemaLocation="http://www.zkoss.org/2005/zul http://www.zkoss.org/2005/zul/zul.xsd"
    xmlns:a="http://www.zkoss.org/2005/zk/annotation" use="Test1"
    id="w1" width="600px" title="Test window">
<button id="b1" label="Increment" onClick="w1.increment()"/>
<separator width="20px"/>
<label id="lbl" value="Not initialized."/>
</window>

The corresponding  Java resource Test1.java is:

import org.zkoss.zul.Label;
import org.zkoss.zul.Window;

@SuppressWarnings("serial")
public class Test1 extends Window {

	public void onCreate() {
		setValue(start);
	}

	public void increment() {
		setValue(++start);
	}

	private void setValue(int v) {
		Label l = (Label)getFellow("lbl");
		l.setValue(Integer.toString(v));
	}

	private int start = 1;
}

This page simply increments a counter as the button is pressed.

Now, I am going to press the button a lot, to find out how many times the system actually records the button was pressed. The best way to test it is to write a unit test module, based on Selenium test framework. The button is clicked, then the test waits for 350 milliseconds to process the request. After this, the label is pooled for the next 3 seconds to update. If it is not updating to the expected value at the end of the 3 seconds, the iteration is considered an error.

import java.util.Date;
import com.thoughtworks.selenium.SeleneseTestCase;

public class IncrementTestCase extends SeleneseTestCase {
	@Override
	public void setUp() throws Exception {
		setUp("http://localhost:8080", "*custom /usr/bin/firefox");
	}

	@Override
	public void tearDown() throws Exception {
		super.tearDown();
		selenium.stop();
	}

	public synchronized void testIncrement() throws Exception {
		int errors = 0;
		selenium.open("/testapp/test1.zul");

		int value = 1;
		for (int i = 0; i != 100; i++) {
			selenium.click("//td[text()='Increment']");
			value++;
			Date start = new Date();
			boolean found = false;
			Thread.sleep(350);
			// 3 seconds waiting time
			while (new Date().getTime() - start.getTime() < 3000) {
				String s = selenium.getText("//span[@class='z-label']");
				if (Integer.parseInt(s) == value) {
					found = true;
					break;
				}
				Thread.sleep(100);
			}
			if (!found) {
				String s = selenium.getText("//span[@class='z-label']");
				System.out.println("Expected: "+ value + " found " + s);
				value = Integer.parseInt(s);
				errors++;
			}
			System.out.println(new Date().toString() + " Errors: "+ errors + " Loops: " + (i+1));
		}
		System.out.println("Errors: "+ errors);
	}
}

The following output results after the execution of the test:

Sun Feb 01 14:03:08 EST 2009 Errors: 0 Loops: 1
Sun Feb 01 14:03:09 EST 2009 Errors: 0 Loops: 2
Expected: 4 found 3
Sun Feb 01 14:03:12 EST 2009 Errors: 1 Loops: 3
Sun Feb 01 14:03:12 EST 2009 Errors: 1 Loops: 4
Sun Feb 01 14:03:13 EST 2009 Errors: 1 Loops: 5
Expected: 6 found 5
Sun Feb 01 14:03:16 EST 2009 Errors: 2 Loops: 6
Sun Feb 01 14:03:16 EST 2009 Errors: 2 Loops: 7
Expected: 7 found 6
Sun Feb 01 14:03:19 EST 2009 Errors: 3 Loops: 8
Sun Feb 01 14:03:20 EST 2009 Errors: 3 Loops: 9
Sun Feb 01 14:03:20 EST 2009 Errors: 3 Loops: 10
Expected: 9 found 8
Sun Feb 01 14:03:23 EST 2009 Errors: 4 Loops: 11
Sun Feb 01 14:03:24 EST 2009 Errors: 4 Loops: 12
Sun Feb 01 14:03:24 EST 2009 Errors: 4 Loops: 13
Sun Feb 01 14:03:24 EST 2009 Errors: 4 Loops: 14
Sun Feb 01 14:03:25 EST 2009 Errors: 4 Loops: 15
Expected: 13 found 12
Sun Feb 01 14:03:28 EST 2009 Errors: 5 Loops: 16
Sun Feb 01 14:03:28 EST 2009 Errors: 5 Loops: 17
Expected: 14 found 13
Sun Feb 01 14:03:31 EST 2009 Errors: 6 Loops: 18
Sun Feb 01 14:03:32 EST 2009 Errors: 6 Loops: 19
Expected: 15 found 14
Sun Feb 01 14:03:35 EST 2009 Errors: 7 Loops: 20
Sun Feb 01 14:03:35 EST 2009 Errors: 7 Loops: 21
Sun Feb 01 14:03:35 EST 2009 Errors: 7 Loops: 22
Expected: 17 found 16
Sun Feb 01 14:03:39 EST 2009 Errors: 8 Loops: 23
Sun Feb 01 14:03:39 EST 2009 Errors: 8 Loops: 24
Sun Feb 01 14:03:39 EST 2009 Errors: 8 Loops: 25
Sun Feb 01 14:03:40 EST 2009 Errors: 8 Loops: 26
Sun Feb 01 14:03:40 EST 2009 Errors: 8 Loops: 27
Sun Feb 01 14:03:40 EST 2009 Errors: 8 Loops: 28
Expected: 22 found 21
Sun Feb 01 14:03:44 EST 2009 Errors: 9 Loops: 29
Sun Feb 01 14:03:44 EST 2009 Errors: 9 Loops: 30
Expected: 23 found 22
Sun Feb 01 14:03:47 EST 2009 Errors: 10 Loops: 31
Sun Feb 01 14:03:48 EST 2009 Errors: 10 Loops: 32
Sun Feb 01 14:03:48 EST 2009 Errors: 10 Loops: 33
Expected: 25 found 24
Sun Feb 01 14:03:51 EST 2009 Errors: 11 Loops: 34
Sun Feb 01 14:03:51 EST 2009 Errors: 11 Loops: 35
Sun Feb 01 14:03:52 EST 2009 Errors: 11 Loops: 36
Sun Feb 01 14:03:52 EST 2009 Errors: 11 Loops: 37
Expected: 28 found 27
Sun Feb 01 14:03:55 EST 2009 Errors: 12 Loops: 38
Sun Feb 01 14:03:56 EST 2009 Errors: 12 Loops: 39
Sun Feb 01 14:03:56 EST 2009 Errors: 12 Loops: 40
Expected: 30 found 29
Sun Feb 01 14:03:59 EST 2009 Errors: 13 Loops: 41
Sun Feb 01 14:04:00 EST 2009 Errors: 13 Loops: 42
Sun Feb 01 14:04:00 EST 2009 Errors: 13 Loops: 43
Sun Feb 01 14:04:00 EST 2009 Errors: 13 Loops: 44
Sun Feb 01 14:04:01 EST 2009 Errors: 13 Loops: 45
Sun Feb 01 14:04:01 EST 2009 Errors: 13 Loops: 46
Sun Feb 01 14:04:02 EST 2009 Errors: 13 Loops: 47
Sun Feb 01 14:04:02 EST 2009 Errors: 13 Loops: 48
Expected: 37 found 36
Sun Feb 01 14:04:05 EST 2009 Errors: 14 Loops: 49
Sun Feb 01 14:04:06 EST 2009 Errors: 14 Loops: 50
Expected: 38 found 37
Sun Feb 01 14:04:09 EST 2009 Errors: 15 Loops: 51
Sun Feb 01 14:04:09 EST 2009 Errors: 15 Loops: 52
Sun Feb 01 14:04:09 EST 2009 Errors: 15 Loops: 53
Expected: 40 found 39
Sun Feb 01 14:04:13 EST 2009 Errors: 16 Loops: 54
Sun Feb 01 14:04:13 EST 2009 Errors: 16 Loops: 55
Sun Feb 01 14:04:13 EST 2009 Errors: 16 Loops: 56
Sun Feb 01 14:04:14 EST 2009 Errors: 16 Loops: 57
Sun Feb 01 14:04:14 EST 2009 Errors: 16 Loops: 58
Expected: 44 found 43
Sun Feb 01 14:04:17 EST 2009 Errors: 17 Loops: 59
Sun Feb 01 14:04:18 EST 2009 Errors: 17 Loops: 60
Expected: 45 found 44
Sun Feb 01 14:04:21 EST 2009 Errors: 18 Loops: 61
Sun Feb 01 14:04:21 EST 2009 Errors: 18 Loops: 62
Sun Feb 01 14:04:22 EST 2009 Errors: 18 Loops: 63
Sun Feb 01 14:04:22 EST 2009 Errors: 18 Loops: 64
Expected: 48 found 47
Sun Feb 01 14:04:25 EST 2009 Errors: 19 Loops: 65
Sun Feb 01 14:04:25 EST 2009 Errors: 19 Loops: 66
Sun Feb 01 14:04:26 EST 2009 Errors: 19 Loops: 67
Sun Feb 01 14:04:26 EST 2009 Errors: 19 Loops: 68
Expected: 51 found 50
Sun Feb 01 14:04:29 EST 2009 Errors: 20 Loops: 69
Sun Feb 01 14:04:30 EST 2009 Errors: 20 Loops: 70
Sun Feb 01 14:04:30 EST 2009 Errors: 20 Loops: 71
Sun Feb 01 14:04:31 EST 2009 Errors: 20 Loops: 72
Sun Feb 01 14:04:31 EST 2009 Errors: 20 Loops: 73
Sun Feb 01 14:04:31 EST 2009 Errors: 20 Loops: 74
Sun Feb 01 14:04:32 EST 2009 Errors: 20 Loops: 75
Sun Feb 01 14:04:32 EST 2009 Errors: 20 Loops: 76
Sun Feb 01 14:04:32 EST 2009 Errors: 20 Loops: 77
Sun Feb 01 14:04:33 EST 2009 Errors: 20 Loops: 78
Expected: 60 found 59
Sun Feb 01 14:04:36 EST 2009 Errors: 21 Loops: 79
Sun Feb 01 14:04:36 EST 2009 Errors: 21 Loops: 80
Sun Feb 01 14:04:37 EST 2009 Errors: 21 Loops: 81
Sun Feb 01 14:04:37 EST 2009 Errors: 21 Loops: 82
Sun Feb 01 14:04:38 EST 2009 Errors: 21 Loops: 83
Sun Feb 01 14:04:38 EST 2009 Errors: 21 Loops: 84
Expected: 65 found 64
Sun Feb 01 14:04:41 EST 2009 Errors: 22 Loops: 85
Sun Feb 01 14:04:42 EST 2009 Errors: 22 Loops: 86
Sun Feb 01 14:04:42 EST 2009 Errors: 22 Loops: 87
Expected: 67 found 66
Sun Feb 01 14:04:45 EST 2009 Errors: 23 Loops: 88
Sun Feb 01 14:04:45 EST 2009 Errors: 23 Loops: 89
Expected: 68 found 67
Sun Feb 01 14:04:49 EST 2009 Errors: 24 Loops: 90
Sun Feb 01 14:04:49 EST 2009 Errors: 24 Loops: 91
Sun Feb 01 14:04:49 EST 2009 Errors: 24 Loops: 92
Expected: 70 found 69
Sun Feb 01 14:04:52 EST 2009 Errors: 25 Loops: 93
Sun Feb 01 14:04:53 EST 2009 Errors: 25 Loops: 94
Expected: 71 found 70
Sun Feb 01 14:04:56 EST 2009 Errors: 26 Loops: 95
Sun Feb 01 14:04:57 EST 2009 Errors: 26 Loops: 96
Sun Feb 01 14:04:57 EST 2009 Errors: 26 Loops: 97
Expected: 73 found 72
Sun Feb 01 14:05:00 EST 2009 Errors: 27 Loops: 98
Sun Feb 01 14:05:00 EST 2009 Errors: 27 Loops: 99
Sun Feb 01 14:05:01 EST 2009 Errors: 27 Loops: 100
Errors: 27

Even after multiple executions, the errors are not occurring consecutively. If this would happen randomly, the chances of occurrence of at least two consecutive errors in 100, with 27% occurrence rate is quite high. It never happened, even after running multiple tests. The reason seams to be the 3 seconds delay of pooling  when reading a bad label value in case of an error. It seams ZK increases the probability of ignoring an event if this event comes right after another one. If the delay between clicks is increased (the red source code line), meaning the delay between requests is bigger, the error rate decreases, even reaches 0.

200 ms      50%

300 ms   27%

500 ms    0%

1000 ms  0%

I have always attempted to prevent usual web application users to submit a form twice (by disabling the submit button after the first submit) but my administrative interfaces model a complex data interaction, requiring a constant client-server interaction. The user is allowed to press a button more than once at very short intervals, for example by pressing the buttons “Up” or “Down” to specify the order of the elements in a list.

Another even simpler test is to send a given amount of clicks and then to evaluate how many clicks were accounted on the server side:

	public void testIncrement2() throws Exception {
		selenium.open("/testapp/test1.zul");

		for (int i = 0; i != 100; i++) {
			selenium.click("//td[text()='Increment']");
			Thread.sleep(350);
		}
		String s = selenium.getText("//span[@class='z-label']");
		int val = Integer.parseInt(s);
		System.out.println("Value: "+val+ " expected: 101");
	}

For a delay of 350 between requests, we receive an error rate of 49 clicks. For a delay of 100 milliseconds not less than 77 clicks fails to be recorded. The failure rate decreases as the request frequency decreases: for a delay of one second, the error rate is 0 and for 50 microseconds it is 81 percent!

In conclusion, I won’t recommend the usage of ZK in any application requiring a lot of client-server roundtrips. I have never tested their commercial version, they claim a substantial performance gain. I assume if the bug is still there, it only occurs less often.

Advertisements