Symptoms

Provisioning "Panel_6_0" for APS application Parallels Plesk Panel task fails with the following error output:

APS Application Error:
406 Not Acceptable
[ApplicationUnknownError] Provisioning: resource 9f69d4dd-ae85-43f7-8723-ce8847545f94 of type 'panels' (http://www.parallels.com/aps/plesk/panel/1.2) for APS application 'Parallels Plesk Panel-1.2-0': P100001: Operation failed; details:
...
[application/aps] Saving to: STDOUT 0K .......... .......... .......... .......... .......... 0% 41.7M 0s 50K .......... ... 0% 1.03M=0.01s Cannot write to - (Success).].

Cause

Guest Tools are outdated inside the VM, where Plesk is getting provisioned. Recent versions of the tools have a new "prl_cat" binary included that is used during provisioning.

Resolution

Update Guest Tools inside the VM.

In case VM templates have outdated tools version as well, it is advised to update them everywhere.

Troubleshooting

Check /var/log/PACI/paci.log on OA MN server and find the request that led to the error:

2016-02-17 04:47:12,280 -3d51- INFO  LoggingFilter [apsc(3)] - 16448 * [PACI<-IM] Client in-bound response
16448 < 200
16448 < x-callback: true
16448 < Date: Wed, 17 Feb 2016 03:47:12 GMT
16448 < Content-Length: 27
16448 < x-paci-request-id: 6bd7f46d-d769-46d9-8564-f9c19ebfc94f
16448 < server: grizzly/2.2.21
16448 < Connection: close
16448 < Content-Type: text/plain
16448 <
Put file has been initiated

2016-02-17 04:47:12,280 -3d51- DEBUG ConcurrentTimedMatcher [apsc(3)] - checkIn(/8303d18c-5f81-4590-8ed4-8c9a378fcdab, ...)
2016-02-17 04:47:22,432 -- DEBUG RESTCallbackListener [IM-Callback(2)] - Got IM callback, uri = [/8303d18c-5f81-4590-8ed4-8c9a378fcdab], rc = [-1]
2016-02-17 04:47:22,432 -- DEBUG ConcurrentTimedMatcher [IM-Callback(2)] - checkOut(/8303d18c-5f81-4590-8ed4-8c9a378fcdab, ...)
2016-02-17 04:47:22,433 -3d51- INFO  LoggingFilter [apsc(3)] - 15697 * Server out-bound response
15697 < 406
15697 < Content-Type: text/plain
15697 < Cache-Control: max-age=0
15697 <
P100001: Operation failed; details: ... HTTP request sent, awaiting response... 200 OK Length: 8471388 (8.1M) [application/aps] Saving to:  STDOUT        0K .......... .......... .......... .......... ..........  0% 41.7M 0s     50K .......... ...                                          0% 1.03M=0.01s   Cannot write to  -  (Success).]

Copy the ID of the request from this line:

16448 < x-paci-request-id: 6bd7f46d-d769-46d9-8564-f9c19ebfc94f

And search for this request ID in /var/log/IM/PACI-vm2vf.log on IM server to see what happens:

2016-02-17 04:47:12,299 (6bd7f46d-d769-46d9-8564-f9c19ebfc94f) INFO  LoggingProxy [RequestProcessor-6276] - invoked: register_callback(
2016-02-17 04:47:12,300 (6bd7f46d-d769-46d9-8564-f9c19ebfc94f) INFO  NativeVm2VfCode [RequestProcessor-6276] - [24541:3830814] INF ==== found mutex for 172.16.0.4 @[common/common_lib.c][575][establish_connection_ex][3880])
2016-02-17 04:47:12,430 (6bd7f46d-d769-46d9-8564-f9c19ebfc94f) DEBUG NativeVm2VfCode [RequestProcessor-6276] - [24541:3830814] Callback invocation: set_handle(139812126297624)
2016-02-17 04:47:12,508 (6bd7f46d-d769-46d9-8564-f9c19ebfc94f) INFO  NativeVm2VfCode [Thread-293158] - [24541:3830814] INF cmd: set -o pipefail ; wget --no-check-certificate --header 'Accept: application/aps' -O - 'https://172.16.0.3:6308//aps/2/packages/5089cc41-810f-433a-a958-bd75670f9aba' | prlctl exec {2d165850-f906-465b-8df3-487ef4abdbd7} prl_cat 'C:\Program Files\APS\9f69d4dd-ae85-43f7-8723-ce8847545f94\package.zip' @[exec.c][728][wget_thread][5130])
2016-02-17 04:47:12,512 (6bd7f46d-d769-46d9-8564-f9c19ebfc94f) DEBUG NativeVm2VfCode [Thread-293159] - [24541:3830814] DBG fd=76 @[exec.c][258][read_string][5130])
2016-02-17 04:47:22,413 (6bd7f46d-d769-46d9-8564-f9c19ebfc94f) DEBUG NativeVm2VfCode [Thread-293160] - [24541:3830814] DBG fd=76 closed len=2072 @[exec.c][281][read_string][5130])
2016-02-17 04:47:22,413 (6bd7f46d-d769-46d9-8564-f9c19ebfc94f) DEBUG NativeVm2VfCode [Thread-293161] - [24541:3830814] DBG stderr =
2016-02-17 04:47:22,413 (6bd7f46d-d769-46d9-8564-f9c19ebfc94f) ERROR NativeVm2VfCode [Thread-293162] - [24541:3830814] ERR [{2d165850-f906-465b-8df3-487ef4abdbd7}] put_file failure: exit_code 2
2016-02-17 04:47:22,416 (6bd7f46d-d769-46d9-8564-f9c19ebfc94f) INFO  NativeVm2VfCode [Thread-293163] - [24541:3830814] INF put cached connection: session uuid: "{70bbf576-a213-4414-b6eb-0f30029c09e9}", session handle 0xface, ref count 1 @[common/common_lib.c][729][drop_connection][5130])
2016-02-17 04:47:22,416 (6bd7f46d-d769-46d9-8564-f9c19ebfc94f) DEBUG NativeVm2VfCode [Thread-293164] - [24541:3830814] Callback invocation: done_with_message(-2147483632, 5880159666763202560, Warning: Permanently added '172.16.0.3' (RSA) to the list of known hosts.

Now the same operation can be tried on the target hardware node 172.16.0.4:

[root@pcs01 ~]# wget --no-check-certificate --header 'Accept: application/aps' -O - 'https://172.16.0.3:6308//aps/2/packages/5089cc41-810f-433a-a958-bd75670f9aba' | prlctl exec {2d165850-f906-465b-8df3-487ef4abdbd7} prl_cat 'C:\Program Files\APS\9f69d4dd-ae85-43f7-8723-ce8847545f94\package.zip'
--2016-02-17 04:22:13--  https://172.16.0.3:6308//aps/2/packages/5089cc41-810f-433a-a958-bd75670f9aba
Connecting to 172.16.0.3:6308... connected.
HTTP request sent, awaiting response... 200 OK
Length: 8471388 (8.1M) [application/aps]
Saving to: Б-°STDOUTБ-?

 0% [>                                                                                                                                                                  ] 65,303      --.-K/s   in 0.001s

Cannot write to - (Success).

As a part of the command above, prlctl exec is launched with prl_cat command, trying to run it manually inside the VM shows that the command is not found:

[root@pcs01 ~]# prlctl enter test_vm
Microsoft Windows [Version 6.3.9600]
(c) 2013 Microsoft Corporation. All rights reserved.

C:\>prl_cat
prl_cat

C:\>'prl_cat' is not recognized as an internal or external command,
operable program or batch file.

Internal content