Core: custom/special operation causes timeout

[tvogt]

I'm following the manual on implementing custom operations and my result is a timeout, tried this with GET, PUT and PATCH (PUT is what I actually needed, the rest I tried to narrow down the problem).

I might be doing something wrong, but in any case the server should not stall. Here is my entity configuration:

/**
 * @ORM\Entity
 * @ApiResource(
 *     attributes={
 *          "access_control"="is_granted('ROLE_USER')",
 *          "normalization_context"={"groups"={"caravan_read"}},
 *          "denormalization_context"={"groups"={"caravan_write"}}
 *     },
 *     collectionOperations={"post"},
 *     itemOperations={"get", "commit"={
 *         "method"="GET",
 *         "path"="/caravans/{id}/commit",
 *         "controller"="App\Controller\CaravanCommit",
 *         "denormalization_context"={"groups"={"caravan_send"}},
 *         "swagger_context" = {
 *              "summary" = "send the caravan on its way"            
 *         },
 *     }},
 *     )
 */

and here is my Controller, which for all I can see does not even get called (though it does get checked, if I remove the __invoke() method, an error results):

<?php

namespace App\Controller;

use App\Entity\Caravan;
use App\Service\CaravanManager;


class CaravanCommit {

    private $caravan_manager;

    public function __construct(CaravanManager $caravan_manager) {
        $this->caravan_manager = $caravan_manager;
    }

    public function __invoke(Caravan $data): Caravan {
        var_dump($data);
        //$this->caravan_manager->send($data);

        return $data;
    }
}

[dunglas]

Can you provide the logs (if any) or use XDebug to see where it hangs?

[tvogt]

there is nothing in the logs at all. I've not yet attached XDebug. I can replicate the problem with a different configuration:

/**
 * @ORM\Entity
 * @ApiResource(
 *     attributes={
 *          "access_control"="is_granted('ROLE_USER') and object.owner.user==user and object.owner.class=='merchant'",
 *          "normalization_context"={"groups"={"caravan_read"}},
 *          "denormalization_context"={"groups"={"caravan_write"}}
 *     },
 *     collectionOperations={"post"},
 *     itemOperations={"get",
 *          "commit"={
 *              "method"="PATCH",
 *              "path"="/caravans/{id}/commit",
 *              "controller"=App\Controller\CaravanAction::class
 *          }
 *     },
 *     )
 */

and

<?php

namespace App\Controller;

use App\Entity\Caravan;
use App\Service\CaravanManager;


class CaravanAction {

    private $caravan_manager;

    public function __construct(CaravanManager $caravan_manager) {
        $this->caravan_manager = $caravan_manager;
    }

    public function __invoke(Caravan $data): Caravan {
        var_dump($data);
        //$this->caravan_manager->send($data);

        return $data;
    }
}

[tvogt]

This is what I see on the screen in Swagger UI. It stands like this (animated "loading") for minutes.

[tvogt]

And here is the debug from dev.log - it ends with an SQL statement that executes perfectly fine (and fast) when I put it into psql directly.

[2018-06-18 13:09:11] request.INFO: Matched route "api_caravans_commit_item". {"route":"api_caravans_commit_item","route_parameters":{"_route":"api_caravans_commit_item","_controller":"App\\Controller\\CaravanAction","_format":null,"_api_resource_class":"App\\Entity\\Caravan","_api_item_operation_name":"commit","id":"1"},"request_uri":"http://caravans-server.test/api/caravans/1/commit","method":"PATCH"} []
[2018-06-18 13:09:11] security.DEBUG: Checking for guard authentication credentials. {"firewall_key":"api","authenticators":1} []
[2018-06-18 13:09:11] security.DEBUG: Calling getCredentials() on guard configurator. {"firewall_key":"api","authenticator":"Lexik\\Bundle\\JWTAuthenticationBundle\\Security\\Guard\\JWTTokenAuthenticator"} []
[2018-06-18 13:09:11] security.DEBUG: Passing guard token information to the GuardAuthenticationProvider {"firewall_key":"api","authenticator":"Lexik\\Bundle\\JWTAuthenticationBundle\\Security\\Guard\\JWTTokenAuthenticator"} []
[2018-06-18 13:09:11] doctrine.DEBUG: SELECT a0_.id AS id_0, a0_.username AS username_1, a0_.password AS password_2, a0_.email AS email_3, a0_.is_active AS is_active_4 FROM app_user a0_ WHERE a0_.username = ? OR a0_.email = ? ["Charlie","Charlie"] []
[2018-06-18 13:09:11] doctrine.DEBUG: SELECT t0.id AS id_1, t0.name AS name_2, t0.class AS class_3, t0.money AS money_4, t0.user_id AS user_id_5, t0.location_id AS location_id_6, t0.location_info_id AS location_info_id_7 FROM character t0 WHERE t0.user_id = ? [3] []
[2018-06-18 13:09:11] php.INFO: User Deprecated: Calling Symfony\Component\Security\Core\User\UserChecker::checkPreAuth with an AdvancedUserInterface is deprecated since Symfony 4.1. Create a custom user checker if you wish to keep this functionality. {"exception":"[object] (ErrorException(code: 0): User Deprecated: Calling Symfony\\Component\\Security\\Core\\User\\UserChecker::checkPreAuth with an AdvancedUserInterface is deprecated since Symfony 4.1. Create a custom user checker if you wish to keep this functionality. at /Users/tom/Code/caravans-server/vendor/symfony/security/Core/User/UserChecker.php:36)"} []
[2018-06-18 13:09:11] php.INFO: User Deprecated: Calling Symfony\Component\Security\Core\User\UserChecker::checkPostAuth with an AdvancedUserInterface is deprecated since Symfony 4.1. Create a custom user checker if you wish to keep this functionality. {"exception":"[object] (ErrorException(code: 0): User Deprecated: Calling Symfony\\Component\\Security\\Core\\User\\UserChecker::checkPostAuth with an AdvancedUserInterface is deprecated since Symfony 4.1. Create a custom user checker if you wish to keep this functionality. at /Users/tom/Code/caravans-server/vendor/symfony/security/Core/User/UserChecker.php:68)"} []
[2018-06-18 13:09:11] security.INFO: Guard authentication successful! {"token":"[object] (Lexik\\Bundle\\JWTAuthenticationBundle\\Security\\Authentication\\Token\\JWTUserToken: JWTUserToken(user=\"Charlie\", authenticated=true, roles=\"ROLE_ADMIN\"))","authenticator":"Lexik\\Bundle\\JWTAuthenticationBundle\\Security\\Guard\\JWTTokenAuthenticator"} []
[2018-06-18 13:09:11] security.DEBUG: Guard authenticator set no success response: request continues. {"authenticator":"Lexik\\Bundle\\JWTAuthenticationBundle\\Security\\Guard\\JWTTokenAuthenticator"} []
[2018-06-18 13:09:11] security.DEBUG: Remember me skipped: it is not configured for the firewall. {"authenticator":"Lexik\\Bundle\\JWTAuthenticationBundle\\Security\\Guard\\JWTTokenAuthenticator"} []
[2018-06-18 13:09:11] doctrine.DEBUG: SELECT c0_.id AS id_0, c0_.money AS money_1, c0_.progress AS progress_2, c0_.left_at AS left_at_3, c0_.expected_return AS expected_return_4, w1_.id AS id_5, w1_.pos AS pos_6, c0_.owner_id AS owner_id_7, c0_.current_waypoint_id AS current_waypoint_id_8, c0_.location_id AS location_id_9, c0_.road_id AS road_id_10, w1_.caravan_id AS caravan_id_11, w1_.road_id AS road_id_12, w1_.destination_id AS destination_id_13 FROM caravan c0_ LEFT JOIN waypoint w1_ ON c0_.id = w1_.caravan_id WHERE c0_.id = ? ORDER BY w1_.pos ASC [1] []

[zazoomauro]

@tvogt any update? I have the same issue

[er1z]

Timeout per se or hang spinner in UI? What does the browser devtools console show?

[RidouaneHicham]

I got the same issue. a GET to one of my entities just stopped working (30s timeout). Nothing custom in my case just a regular GET operation..

[ahmed-bhs]

@zazoomauro same problem, any idea ?
I disabled the persisted event, and the issue is gone, but I need to call the entity manager to persist. I think the issue cames from the data persister of apiplatform.

[fabienlege]

Same issue !
Always nothing on it ?