Wsrtjtyk

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.