Article ID: 124457, created on Feb 14, 2015, last review on Mar 7, 2015

  • Applies to:
  • Plesk Automation 11.5

Symptoms

Subscription provisioning from PBAS to PPA fails with error:

    Error message or request description :  Process provisioning for document; subscription upgrading failed: RPC::XML::Client::send_request: HTTP server error: Timeout

From poa.debug.log, last operation for subscription looks as below and method pem.setResourceTypeLimits is not finished:

    ppa : DBG [openapi:1.2.3.4:441264 1:1304:ad8fcb70 Kernel]: STMT [Con: 30539, 0xadc0d620 txn:1117895] ' SELECT 1  FROM subscriptions WHERE sub_id =  ? FOR UPDATE'($0 = 15)

Additionally in poa.debug.log:

    ppa : DBG [task:6332:264996 1:1304:b13e7b70 Kernel]: STMT [Con: 22376, 0x89368e8 txn:989724 task:6332] ' UPDATE domains SET hosting_res =  ? , management_res =  ? WHERE domain_id =  ?'($0 = 0, $1 = 0, $2 = 188)
    ...
    : DBG [task:6332:264996 1:1362:b3866b70 TaskManager]: [task:6332 Tasks::impl::TaskImpl::process] ===> ENTRY
    ppa : DBG [task:6332:264996 1:1362:b3866b70 lib]: [Tasks::impl::TaskImpl::process] {module_id="Common"; code="104"} Request has been timed out, details:
    system exception, ID 'IDL:omg.org/CORBA/TIMEOUT:1.0'
    TAO exception, minor code = 3e (timeout during recv; low 7 bits of errno:  62 Timer expired), completed = MAYBE

Cause

Deadlock operation in PostgreSQL database. PPA did not close PostgreSQL transaction if some error occurs. If lock to some table is acquired in transaction, all next lock requests to the same table are blocked.

This is PPA internal issue with id #PPA-2313 and is expected to be fixed in future PPA updates.

Resolution

While there is no released hotfix, please use the mentioned workaround.

  1. To make sure that deadlock for some database operation is detected, find how many rows are locked for "subscription":

    plesk=> select oid from pg_class where relname = 'subscriptions';
      oid  
    
    -------
    
    16422
    (1 row)
    
  2. Find all locked operations using the following query:

    plesk=> select pid,mode,granted,backend_start,query_start,current_query from pg_locks inner join pg_stat_activity on pid = procpid where relation = 16422 order by query_start;
      pid  |      mode       | granted |         backend_start         |          query_start          |                                   current_query                                   
    -------+-----------------+---------+-------------------------------+-------------------------------+-----------------------------------------------------------------------------------
     22376 | AccessShareLock | t       | 2015-02-05 22:52:49.314068-05 | 2015-02-05 22:52:55.945924-05 |  UPDATE domains SET hosting_res =  0 , management_res =  0 WHERE domain_id =  188
     22377 | RowShareLock    | t       | 2015-02-05 22:52:49.312905-05 | 2015-02-05 22:53:15.671862-05 | <IDLE> in transaction
     22377 | AccessShareLock | t       | 2015-02-05 22:52:49.312905-05 | 2015-02-05 22:53:15.671862-05 | <IDLE> in transaction
     22646 | AccessShareLock | t       | 2015-02-05 22:54:30.01226-05  | 2015-02-05 22:54:52.754733-05 | <IDLE> in transaction
      9537 | ExclusiveLock   | t       | 2015-02-11 12:52:55.219872-05 | 2015-02-11 13:09:16.263751-05 | BEGIN; SELECT 1  FROM subscriptions WHERE sub_id =  15 FOR UPDATE
      9537 | RowShareLock    | t       | 2015-02-11 12:52:55.219872-05 | 2015-02-11 13:09:16.263751-05 | BEGIN; SELECT 1  FROM subscriptions WHERE sub_id =  15 FOR UPDATE
     11445 | ExclusiveLock   | f       | 2015-02-11 13:16:58.936031-05 | 2015-02-11 13:22:49.585983-05 | BEGIN; SELECT 1  FROM subscriptions WHERE sub_id =  15 FOR UPDATE
     11445 | RowShareLock    | t       | 2015-02-11 13:16:58.936031-05 | 2015-02-11 13:22:49.585983-05 | BEGIN; SELECT 1  FROM subscriptions WHERE sub_id =  15 FOR UPDATE
      9086 | RowShareLock    | t       | 2015-02-11 18:15:30.014296-05 | 2015-02-11 18:16:31.79709-05  | BEGIN; SELECT 1  FROM subscriptions WHERE sub_id =  15 FOR UPDATE
      9086 | ExclusiveLock   | f       | 2015-02-11 18:15:30.014296-05 | 2015-02-11 18:16:31.79709-05  | BEGIN; SELECT 1  FROM subscriptions WHERE sub_id =  15 FOR UPDATE
     15385 | ExclusiveLock   | f       | 2015-02-11 23:26:22.013902-05 | 2015-02-11
     ...........
    
  3. Drop existing connections as below:

    # su postgres
    # psql
    postgres=# select pg_terminate_backend(22376);
     pg_terminate_backend
    
    ----------------------
    
    t
    (1 row)
    
    postgres=# select pg_terminate_backend(22377);
     pg_terminate_backend
    
    ----------------------
    
    t
    (1 row)
    
    postgres=# select pg_terminate_backend(22646);
     pg_terminate_backend
    
    ----------------------
    
    t
    (1 row)
    
  4. Make sure that locked operations are disappeared:

    postgres=# select pid,mode,granted,backend_start,query_start,current_query from pg_locks inner join pg_stat_activity on pid = procpid where relation = 16422 order by query_start;
      pid  |      mode       | granted |         backend_start         |          query_start          |     current_query     
    -------+-----------------+---------+-------------------------------+-------------------------------+-----------------------
     21418 | RowShareLock    | t       | 2015-02-12 07:21:19.342282-05 | 2015-02-12 07:27:26.128134-05 | <IDLE> in transaction
     21418 | AccessShareLock | t       | 2015-02-12 07:21:19.342282-05 | 2015-02-12 07:27:26.128134-05 | <IDLE> in transaction
    (2 rows)
    

    These are idle state processes only left, it is normal behaviour.

  5. Try to provision subscription from PBAS to PPA once again.

Search Words

subscription upgrading failed

Process provisioning for document; subscription upgrading failed: RPC::XML::Client::send_request: HTTP server error: Timeout

subscription upgrading failed: RPC::XML::Client::send_request: HTTP server error: Timeout

33a70544d00d562bbc5b17762c4ed2b3 caea8340e2d186a540518d08602aa065 e0aff7830fa22f92062ee4db78133079

Email subscription for changes to this article
Save as PDF