Pfthb

I'm trying to load data from the server. The loaded data is then displayed via JavaFX views. I'm using a service to perform networking operations, I'm using Apache HttpClients for this. Initially, I thought the bug was associated with the network. I've done some caveman style debugging and come to realize that the bug is associated with the service. Weirdly, the service invokes the onSucceeded() method when it is run for the second (different instance, I'm not restarting the service). I'm not able to figure out why the service invokes the onSucceeded() method only the second time.

Here's the service class I've implemented for performing the networking operations.

public class HttpClientService extends Service<String> 

 private static final String TAG = HttpClientService.class.getName();
 private static final Logger logger = Logger.getLogger(TAG);

 private ObjectProperty<URL> url = new SimpleObjectProperty<>();
 private ObservableList<NameValuePair> parameters = FXCollections.observableArrayList();

 public HttpClientService(String url, Map<String, String> map) throws MalformedURLException 
 setUrl(new URL(url));
 for (String name : map.keySet()) 
 String value = map.get(name);
 parameters.add(new BasicNameValuePair(name, value));
 
 

 public HttpClientService(String url, NameValuePair ... parameters) throws MalformedURLException 
 setUrl(new URL(url));
 getParameters().addAll(parameters);
 

 public HttpClientService(URL url, NameValuePair ... parameters) 
 setUrl(url);
 getParameters().addAll(parameters);
 

 protected Task<String> createTask() 
 return new HttpClientTask(getUrl(), getParameters());
 

 public URL getUrl() 
 return url.get();
 

 public ObjectProperty<URL> urlProperty() 
 return url;
 

 public void setUrl(URL url) 
 this.url.set(url);
 

 public ObservableList<NameValuePair> getParameters() 
 return parameters;
 

 public void setParameters(ObservableList<NameValuePair> parameters) 
 this.parameters = parameters;
 

 @Override
 protected void succeeded() 
 System.out.println("## Successful...");
 

 @Override
 protected void failed() 
 Throwable exception = getException();

 System.out.println("Error: Failed to download guest profiles.");
 exception.printStackTrace();
 

 @Override
 protected void cancelled() 
 System.out.println("HttpClientService was stopped.");
 

 @Override
 protected void running() 
 logger.log(Level.INFO, "Running service...");
 

Here's the method which invokes the service and injects the data into a view.

private void loadBlocks() 
 try 
 // TODO: Get the property identifier and set!
 Integer propertyIdentifier = 1;

 Map<String, String> parameters = new HashMap<>();
 parameters.put("property", propertyIdentifier.toString());

 HttpClientService service = new HttpClientService(UrlPath.ADMINISTRATION_PROPERTY_BLOCK_LIST_ALL, parameters);
 service.setOnSucceeded(workerStateEvent -> 
 logger.log(Level.INFO, "Successfully loaded blocks");

 try 
 String result = (String)workerStateEvent.getSource().getValue();
 logger.log(Level.INFO, result);

 List<Block> blocks = mapper.readValue(result, new TypeReference<ArrayList<Block>>());

 ObservableList<Block> items = blocksTableView.getItems();
 items.clear();
 items.addAll(blocks);

 NotificationHelper.postNotification(eventBus, "Successfully loaded blocks", 500);
 
 catch (IOException exception) 
 exception.printStackTrace();
 
 );
 service.stateProperty().addListener((observableValue, state, t1) -> System.out.println(t1));
 service.start();
 
 catch (MalformedURLException exception) 
 exception.printStackTrace();
 

Here's the log of the application.

SCHEDULED
RUNNING
Nov 10, 2018 2:28:26 PM com.onecube.pms.client.service.HttpClientService running
INFO: Running service...
Nov 10, 2018 2:28:26 PM com.onecube.pms.client.task.HttpClientTask call
INFO: [Content-Type: application/x-www-form-urlencoded,Content-Length: 10,Chunked: false]
14:28:26.778 [Thread-3] DEBUG org.apache.http.client.protocol.RequestAddCookies - CookieSpec selected: default
14:28:26.794 [Thread-3] DEBUG org.apache.http.client.protocol.RequestAuthCache - Auth cache not set in the context
14:28:26.796 [Thread-3] DEBUG org.apache.http.impl.conn.PoolingHttpClientConnectionManager - Connection request: [route: ->http://localhost:8080][total kept alive: 0; route allocated: 0 of 100; total allocated: 0 of 200]
14:28:26.809 [Thread-3] DEBUG org.apache.http.impl.conn.PoolingHttpClientConnectionManager - Connection leased: [id: 0][route: ->http://localhost:8080][total kept alive: 0; route allocated: 1 of 100; total allocated: 1 of 200]
14:28:26.810 [Thread-3] DEBUG org.apache.http.impl.execchain.MainClientExec - Opening connection ->http://localhost:8080
14:28:26.829 [Thread-3] DEBUG org.apache.http.impl.conn.DefaultHttpClientConnectionOperator - Connecting to localhost/127.0.0.1:8080
14:28:26.830 [Thread-3] DEBUG org.apache.http.impl.conn.DefaultHttpClientConnectionOperator - Connection established 127.0.0.1:63671<->127.0.0.1:8080
14:28:26.831 [Thread-3] DEBUG org.apache.http.impl.execchain.MainClientExec - Executing request POST /administration/property/block/listAll HTTP/1.1
14:28:26.831 [Thread-3] DEBUG org.apache.http.impl.execchain.MainClientExec - Target auth state: UNCHALLENGED
14:28:26.834 [Thread-3] DEBUG org.apache.http.impl.execchain.MainClientExec - Proxy auth state: UNCHALLENGED
14:28:26.836 [Thread-3] DEBUG org.apache.http.headers - http-outgoing-0 >> POST /administration/property/block/listAll HTTP/1.1
14:28:26.836 [Thread-3] DEBUG org.apache.http.headers - http-outgoing-0 >> Content-Length: 10
14:28:26.836 [Thread-3] DEBUG org.apache.http.headers - http-outgoing-0 >> Content-Type: application/x-www-form-urlencoded
14:28:26.836 [Thread-3] DEBUG org.apache.http.headers - http-outgoing-0 >> Host: localhost:8080
14:28:26.836 [Thread-3] DEBUG org.apache.http.headers - http-outgoing-0 >> Connection: Keep-Alive
14:28:26.836 [Thread-3] DEBUG org.apache.http.headers - http-outgoing-0 >> User-Agent: Apache-HttpClient/4.5.6 (Java/11.0.1)
14:28:26.836 [Thread-3] DEBUG org.apache.http.headers - http-outgoing-0 >> Accept-Encoding: gzip,deflate
14:28:26.837 [Thread-3] DEBUG org.apache.http.wire - http-outgoing-0 >> "POST /administration/property/block/listAll HTTP/1.1[r][n]"
14:28:26.837 [Thread-3] DEBUG org.apache.http.wire - http-outgoing-0 >> "Content-Length: 10[r][n]"
14:28:26.837 [Thread-3] DEBUG org.apache.http.wire - http-outgoing-0 >> "Content-Type: application/x-www-form-urlencoded[r][n]"
14:28:26.837 [Thread-3] DEBUG org.apache.http.wire - http-outgoing-0 >> "Host: localhost:8080[r][n]"
14:28:26.837 [Thread-3] DEBUG org.apache.http.wire - http-outgoing-0 >> "Connection: Keep-Alive[r][n]"
14:28:26.837 [Thread-3] DEBUG org.apache.http.wire - http-outgoing-0 >> "User-Agent: Apache-HttpClient/4.5.6 (Java/11.0.1)[r][n]"
14:28:26.837 [Thread-3] DEBUG org.apache.http.wire - http-outgoing-0 >> "Accept-Encoding: gzip,deflate[r][n]"
14:28:26.837 [Thread-3] DEBUG org.apache.http.wire - http-outgoing-0 >> "[r][n]"
14:28:26.838 [Thread-3] DEBUG org.apache.http.wire - http-outgoing-0 >> "property=1"
14:28:26.845 [Thread-3] DEBUG org.apache.http.wire - http-outgoing-0 << "HTTP/1.1 200 [r][n]"
14:28:26.846 [Thread-3] DEBUG org.apache.http.wire - http-outgoing-0 << "Content-Type: application/json;charset=UTF-8[r][n]"
14:28:26.846 [Thread-3] DEBUG org.apache.http.wire - http-outgoing-0 << "Transfer-Encoding: chunked[r][n]"
14:28:26.846 [Thread-3] DEBUG org.apache.http.wire - http-outgoing-0 << "Date: Sat, 10 Nov 2018 08:58:26 GMT[r][n]"
14:28:26.846 [Thread-3] DEBUG org.apache.http.wire - http-outgoing-0 << "[r][n]"
14:28:26.846 [Thread-3] DEBUG org.apache.http.wire - http-outgoing-0 << "2[r][n]"
14:28:26.846 [Thread-3] DEBUG org.apache.http.wire - http-outgoing-0 << "[r][n]"
14:28:26.846 [Thread-3] DEBUG org.apache.http.wire - http-outgoing-0 << "0[r][n]"
14:28:26.846 [Thread-3] DEBUG org.apache.http.wire - http-outgoing-0 << "[r][n]"
14:28:26.850 [Thread-3] DEBUG org.apache.http.headers - http-outgoing-0 << HTTP/1.1 200 
14:28:26.850 [Thread-3] DEBUG org.apache.http.headers - http-outgoing-0 << Content-Type: application/json;charset=UTF-8
java.lang.Throwable
 at com.onecube.pms.client.task.HttpClientTask.call(HttpClientTask.java:81)
 at com.onecube.pms.client.task.HttpClientTask.call(HttpClientTask.java:32)
 at javafx.concurrent.Task$TaskCallable.call(Task.java:1425)
 at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
 at javafx.concurrent.Service.lambda$executeTask$6(Service.java:725)
 at java.base/java.security.AccessController.doPrivileged(Native Method)
 at javafx.concurrent.Service.lambda$executeTask$7(Service.java:724)
 at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
 at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
 at java.base/java.lang.Thread.run(Thread.java:834)
14:28:26.850 [Thread-3] DEBUG org.apache.http.headers - http-outgoing-0 << Transfer-Encoding: chunked
14:28:26.850 [Thread-3] DEBUG org.apache.http.headers - http-outgoing-0 << Date: Sat, 10 Nov 2018 08:58:26 GMT
14:28:26.856 [Thread-3] DEBUG org.apache.http.impl.execchain.MainClientExec - Connection can be kept alive indefinitely
14:28:26.860 [Thread-3] DEBUG org.apache.http.impl.conn.PoolingHttpClientConnectionManager - Connection [id: 0][route: ->http://localhost:8080] can be kept alive indefinitely
14:28:26.861 [Thread-3] DEBUG org.apache.http.impl.conn.DefaultManagedHttpClientConnection - http-outgoing-0: set socket timeout to 0
14:28:26.861 [Thread-3] DEBUG org.apache.http.impl.conn.PoolingHttpClientConnectionManager - Connection released: [id: 0][route: ->http://localhost:8080][total kept alive: 1; route allocated: 1 of 100; total allocated: 1 of 200]
SCHEDULED
RUNNING
Nov 10, 2018 2:28:43 PM com.onecube.pms.client.service.HttpClientService running
INFO: Running service...
Nov 10, 2018 2:28:43 PM com.onecube.pms.client.task.HttpClientTask call
INFO: [Content-Type: application/x-www-form-urlencoded,Content-Length: 10,Chunked: false]
14:28:43.429 [Thread-4] DEBUG org.apache.http.client.protocol.RequestAddCookies - CookieSpec selected: default
14:28:43.430 [Thread-4] DEBUG org.apache.http.client.protocol.RequestAuthCache - Auth cache not set in the context
14:28:43.431 [Thread-4] DEBUG org.apache.http.impl.conn.PoolingHttpClientConnectionManager - Connection request: [route: ->http://localhost:8080][total kept alive: 0; route allocated: 0 of 100; total allocated: 0 of 200]
14:28:43.431 [Thread-4] DEBUG org.apache.http.impl.conn.PoolingHttpClientConnectionManager - Connection leased: [id: 1][route: ->http://localhost:8080][total kept alive: 0; route allocated: 1 of 100; total allocated: 1 of 200]
14:28:43.431 [Thread-4] DEBUG org.apache.http.impl.execchain.MainClientExec - Opening connection ->http://localhost:8080
14:28:43.431 [Thread-4] DEBUG org.apache.http.impl.conn.DefaultHttpClientConnectionOperator - Connecting to localhost/127.0.0.1:8080
14:28:43.432 [Thread-4] DEBUG org.apache.http.impl.conn.DefaultHttpClientConnectionOperator - Connection established 127.0.0.1:63675<->127.0.0.1:8080
14:28:43.432 [Thread-4] DEBUG org.apache.http.impl.execchain.MainClientExec - Executing request POST /administration/property/block/listAll HTTP/1.1
14:28:43.432 [Thread-4] DEBUG org.apache.http.impl.execchain.MainClientExec - Target auth state: UNCHALLENGED
14:28:43.433 [Thread-4] DEBUG org.apache.http.impl.execchain.MainClientExec - Proxy auth state: UNCHALLENGED
14:28:43.433 [Thread-4] DEBUG org.apache.http.headers - http-outgoing-1 >> POST /administration/property/block/listAll HTTP/1.1
14:28:43.434 [Thread-4] DEBUG org.apache.http.headers - http-outgoing-1 >> Content-Length: 10
14:28:43.434 [Thread-4] DEBUG org.apache.http.headers - http-outgoing-1 >> Content-Type: application/x-www-form-urlencoded
14:28:43.434 [Thread-4] DEBUG org.apache.http.headers - http-outgoing-1 >> Host: localhost:8080
14:28:43.434 [Thread-4] DEBUG org.apache.http.headers - http-outgoing-1 >> Connection: Keep-Alive
14:28:43.434 [Thread-4] DEBUG org.apache.http.headers - http-outgoing-1 >> User-Agent: Apache-HttpClient/4.5.6 (Java/11.0.1)
14:28:43.434 [Thread-4] DEBUG org.apache.http.headers - http-outgoing-1 >> Accept-Encoding: gzip,deflate
14:28:43.434 [Thread-4] DEBUG org.apache.http.wire - http-outgoing-1 >> "POST /administration/property/block/listAll HTTP/1.1[r][n]"
14:28:43.434 [Thread-4] DEBUG org.apache.http.wire - http-outgoing-1 >> "Content-Length: 10[r][n]"
14:28:43.434 [Thread-4] DEBUG org.apache.http.wire - http-outgoing-1 >> "Content-Type: application/x-www-form-urlencoded[r][n]"
14:28:43.434 [Thread-4] DEBUG org.apache.http.wire - http-outgoing-1 >> "Host: localhost:8080[r][n]"
14:28:43.434 [Thread-4] DEBUG org.apache.http.wire - http-outgoing-1 >> "Connection: Keep-Alive[r][n]"
14:28:43.434 [Thread-4] DEBUG org.apache.http.wire - http-outgoing-1 >> "User-Agent: Apache-HttpClient/4.5.6 (Java/11.0.1)[r][n]"
14:28:43.434 [Thread-4] DEBUG org.apache.http.wire - http-outgoing-1 >> "Accept-Encoding: gzip,deflate[r][n]"
14:28:43.435 [Thread-4] DEBUG org.apache.http.wire - http-outgoing-1 >> "[r][n]"
14:28:43.435 [Thread-4] DEBUG org.apache.http.wire - http-outgoing-1 >> "property=1"
java.lang.Throwable
 at com.onecube.pms.client.task.HttpClientTask.call(HttpClientTask.java:81)
 at com.onecube.pms.client.task.HttpClientTask.call(HttpClientTask.java:32)
 at javafx.concurrent.Task$TaskCallable.call(Task.java:1425)
 at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
 at javafx.concurrent.Service.lambda$executeTask$6(Service.java:725)
 at java.base/java.security.AccessController.doPrivileged(Native Method)
 at javafx.concurrent.Service.lambda$executeTask$7(Service.java:724)
 at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
 at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
 at java.base/java.lang.Thread.run(Thread.java:834)
Nov 10, 2018 2:28:43 PM com.onecube.pms.client.controller.administration.room.ManageBlocksController lambda$loadBlocks$2
INFO: Successfully loaded blocks
Nov 10, 2018 2:28:43 PM com.onecube.pms.client.controller.administration.room.ManageBlocksController lambda$loadBlocks$2
INFO: 
14:28:43.444 [Thread-4] DEBUG org.apache.http.wire - http-outgoing-1 << "HTTP/1.1 200 [r][n]"
14:28:43.449 [Thread-4] DEBUG org.apache.http.wire - http-outgoing-1 << "Content-Type: application/json;charset=UTF-8[r][n]"
14:28:43.449 [Thread-4] DEBUG org.apache.http.wire - http-outgoing-1 << "Transfer-Encoding: chunked[r][n]"
14:28:43.449 [Thread-4] DEBUG org.apache.http.wire - http-outgoing-1 << "Date: Sat, 10 Nov 2018 08:58:43 GMT[r][n]"
14:28:43.449 [Thread-4] DEBUG org.apache.http.wire - http-outgoing-1 << "[r][n]"
14:28:43.449 [Thread-4] DEBUG org.apache.http.wire - http-outgoing-1 << "2[r][n]"
14:28:43.449 [Thread-4] DEBUG org.apache.http.wire - http-outgoing-1 << "[r][n]"
14:28:43.449 [Thread-4] DEBUG org.apache.http.wire - http-outgoing-1 << "0[r][n]"
14:28:43.449 [Thread-4] DEBUG org.apache.http.wire - http-outgoing-1 << "[r][n]"
14:28:43.450 [Thread-4] DEBUG org.apache.http.headers - http-outgoing-1 << HTTP/1.1 200 
14:28:43.450 [Thread-4] DEBUG org.apache.http.headers - http-outgoing-1 << Content-Type: application/json;charset=UTF-8
14:28:43.450 [Thread-4] DEBUG org.apache.http.headers - http-outgoing-1 << Transfer-Encoding: chunked
14:28:43.451 [Thread-4] DEBUG org.apache.http.headers - http-outgoing-1 << Date: Sat, 10 Nov 2018 08:58:43 GMT
14:28:43.452 [Thread-4] DEBUG org.apache.http.impl.execchain.MainClientExec - Connection can be kept alive indefinitely
14:28:43.453 [Thread-4] DEBUG org.apache.http.impl.conn.PoolingHttpClientConnectionManager - Connection [id: 1][route: ->http://localhost:8080] can be kept alive indefinitely
14:28:43.453 [Thread-4] DEBUG org.apache.http.impl.conn.DefaultManagedHttpClientConnection - http-outgoing-1: set socket timeout to 0
14:28:43.453 [Thread-4] DEBUG org.apache.http.impl.conn.PoolingHttpClientConnectionManager - Connection released: [id: 1][route: ->http://localhost:8080][total kept alive: 1; route allocated: 1 of 100; total allocated: 1 of 200]
## Successful...
SUCCEEDED

From what you show us, your code does not hold a strong reference to the HttpClientService anywhere. This leads me to believe the HttpClientService is being garbage collected before its HttpClientTask completes. Some quick testing confirms this is possible.

To solve this, you need to keep a strong reference to the HttpClientService instance. This can be done by storing it somewhere in the class that loadBlocks() belongs to (assuming said class' instance is also strongly referenced). Then when the service terminates you can remove that reference (since you aren't reusing the service currently). Another solution is to use HttpClientTask directly and only implement using HttpClientService when you're ready.

Note that the HttpClientTask is not garbage collected. This is because it's strongly reachable from the Thread executing it. Consequently, your background task completes normally but there's no longer an HttpClientService to notify you.

Also, there is no difference between the first time you run this code and any subsequent times. The fact it works for the second invocation is simply luck. The HttpClientService is subject to garbage collection every time you invoke this method; however, there's no guarantee a garbage collection cycle will run which means you'll get lucky from time to time.