Symptoms

Task fails with the output:

    Enable WebMatrix Publishing for virtual web server <ID> on host '<FQDN>' (host_id=<HW_ID>, sub_id=<SUB_ID>, domain=s<DOM_ID>.instanturl.tld, w_id=<IIS_WEBSPACE_ID>). failed with timeout error.
    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

Intermediate network equipment between OA MN and WPE terminates the connection prematurely without notifying either ends.

Resolution

Fix the network equipment to allow long network connections with no data exchange.

As an alternative way, analyze why the WPE task takes so long to be finished and decrease the exectution time.

Another possible preventive measure is changing OS TCP keepalive settings to send keepalive probes sooner than the default 2 hours. Linux TCP keepalive documentation:
TCP Keepalive HOWTO

Troubleshooting example

  1. After launching the task, check the connection that gets established from OA MN to WPE, a new client port (36241) is allocated on MN side. Start to monitor the state of the connection with netstat:

    #  while true; do date; netstat -antp | grep 10.10.0.12 | grep 36241 ; sleep 60 ; done

    It provides the snapshots of the output each minute, the presence of the entries confirms that the connection is established:

    Sat Apr 30 16:51:30 EDT 2016
tcp        0      0 10.10.0.11:36241             10.10.0.12:48480           ESTABLISHED 13685/SoLoader
Sat Apr 30 16:52:30 EDT 2016
tcp        0      0 10.10.0.11:36241             10.10.0.12:48480           ESTABLISHED 13685/SoLoader
Sat Apr 30 16:53:31 EDT 2016
tcp        0      0 10.10.0.11:36241             10.10.0.12:48480           ESTABLISHED 13685/SoLoader

  2. The same thing should be done on WPE host (in Powershell):

    PS C:\> while ($true) {date; netstat -ano | findstr 10.10.0.11 | findstr 36241 ; sleep 60}

    The example below shows that the connection is already dropped at 4:39 PM:

    Saturday, April 30, 2016 4:37:27 PM
  TCP    10.10.0.12:48480      10.10.0.11:36241        ESTABLISHED     4
Saturday, April 30, 2016 4:38:27 PM
  TCP    10.10.0.12:48480      10.10.0.11:36241        ESTABLISHED     4
Saturday, April 30, 2016 4:39:27 PM
Saturday, April 30, 2016 4:40:27 PM
Saturday, April 30, 2016 4:41:27 PM

  3. 16:39 is the time, when WPE request finished its execution per WPE logs:

    Find the start of the request execution and fetch the thread ID (in brackets):

    PS C:\> select-string webmatrix wpe.log

wpe.log:256487:DEBUG    2016-04-30 15:00:10 (352/5108): Request summary: Enable WebMatrix Publishing for virtual web server 19082 on host 'web1.example.com' (host_id=1010, sub_id=1010101, domain=test.example.com, w_id=321231).

    Search the ending of this thread ID:

    PS C:\> select-string "352/5108" wpe.log

wpe.log:302061:DEBUG    2016-04-30 15:01:38 (352/5108): Call method "File System Provider::SetDirectoryAttributes"
wpe.log:302062:INFO    2016-04-30 15:01:38 (352/5108): Procedure "File System Provider::SetDirectoryAttributes" - (ENTER)
wpe.log:302063:DEBUG    2016-04-30 15:01:38 (352/5108): Inheritance not changed
wpe.log:443201:INFO    2016-04-30 16:39:11 (352/5108): Procedure "File System Provider::SetDirectoryAttributes" - (EXIT)
wpe.log:443742:INFO    2016-04-30 16:39:11 (352/5108): ----- REQUEST cb428dff-9909-4ca8-a825-d1711203433b is finished
wpe.log:443743:DEBUG    2016-04-30 16:39:11 (352/5108): Request from 10.10.0.11 is handled.
  4. The above outputs mean that the connection got terminated somewhere between OA MN and WPE without notifying either ends, and, as a result, OA MN did not receive any data at all, so the connection remains alive, while WPE sent its final portion of data, having closed the connection.

Internal content