Fix for Word Automation Services Not Working SharePoint 2013

Issue:
Word Automation Services not converting any document in SharePoint 2013.


A bit more details:
Word automation services were configured correctly on a SharePoint 2013 Enterprise farm. Several checks indicated that the service itself is indeed running but no file was able to convert either by back-end code or from Power Shell. Also did not spot any issue from ULS logs.

Farm setup: On-premise SP2013 running on a VMware machines. Word automation service is started on an APP machine.

Digging:
So more digging is required.. fine! Let's check things:

- Timer service is running as well
- Word Automation service application: both Local Farm and service accounts have full control
- Word Automation services Timer Job: succeeded but duration is 0:00:00 (hh:mm:ss)

From ULS: (WARNING: a lengthy log below. Skip to Root Cause section if in a hurry!)

I turned event logging to Verbose. Below is excerpt for entries for 'Word Automation' and 'Office Automation' areas:

Timer 'Word Automation Services': Begin Execute
Service: Finding the App
Timer 'Word Automation Services': Using App 'Word Automation Services'
App 'Word Automation Services': Finding the Proxy
Timer 'Word Automation Services': Using Proxy 'Word Automation Services'
Timer 'Word Automation Services': Retrieving list of worker endpoints
Timer 'Word Automation Services': Retrieving list of items, max 30
Database 'WordAutomationServices_81f5abe0bd144393968855d13700eecc': Connecting with connection string 'Data Source=SP2013DBALIAS_QA;Initial Catalog=WordAutomationServices_81f5abe0bd144393968855d13700eecc;Integrated Security=True;Enlist=False;Pooling=True;Min Pool Size=0;Max Pool Size=100;Connect Timeout=15'
SQL connection time: 0.0418133333333333
Determining if the current user is a SharePoint Farm Administrator
Contacting worker server instance at endpoint http://ServerName:32843/5e8ffcb72f374173832b562cf8a99ba8/Service.svc
Contacting workers; count = 1
Proxy: Creating channel
Proxy: Channel created
WcfSendRequest: RemoteAddress: 'http://ServerName:32843/5e8ffcb72f374173832b562cf8a99ba8/Service.svc' Channel: 'Microsoft.Office.ConversionServices.Service.IConversionServiceApplication' Action...
Waiting up to 15.00 seconds for async responses from worker endpoints
App 'Word Automation Services': GetId
Service: Refreshing the potentially stale App 'Word Automation Services'
App 'Word Automation Services': GetId complete
..
...
Proxy 'Word Automation Services': AddSyncJob 00000000-0000-100a-806a-ff946170b801    00000000-0000-100a-806a-ff946170b801

Proxy 'Word Automation Services': Getting raw partition id from subscription id    00000000-0000-100a-806a-ff946170b801

Local Controller '45dd175f-3798-4740-9200-a5191f5d1185': Total number of sync jobs now increased to 5    00000000-0000-100a-806a-ff946170b801

App 'Word Automation Services': Resolving raw partition id    00000000-0000-100a-806a-ff946170b801

App 'Word Automation Services': Resolved partition id    00000000-0000-100a-806a-ff946170b801

Local Controller '45dd175f-3798-4740-9200-a5191f5d1185': BeginConvert: 00000000-0000-100a-806a-ff946170b801    00000000-0000-100a-806a-ff946170b801

'Word Automation Services': Ensuring temp directory 'C:\Windows\TEMP\wdsrv\0a69ebd3-72c0-4ebf-9ff8-1a7ce971f01d\jo5ou1zi.40z\i435ye3b.g55' exists    00000000-0000-100a-806a-ff946170b801

'Word Automation Services': Creating non-existing temp directory 'C:\Windows\TEMP\wdsrv\0a69ebd3-72c0-4ebf-9ff8-1a7ce971f01d\jo5ou1zi.40z\i435ye3b.g55'    00000000-0000-100a-806a-ff946170b801

App 'Word Automation Services': Created temp directory 'C:\Windows\TEMP\wdsrv\0a69ebd3-72c0-4ebf-9ff8-1a7ce971f01d\jo5ou1zi.40z\i435ye3b.g55'    00000000-0000-100a-806a-ff946170b801

Register a sync job 00000000-0000-100a-806a-ff946170b801    00000000-0000-100a-806a-ff946170b801

Item 00000000-0000-100a-806a-ff946170b801: Worker setting wordEnabledFormats=docx,dotx,docm,dotm,doc,dot,rtf,mht,xml    00000000-0000-100a-806a-ff946170b801

Item 00000000-0000-100a-806a-ff946170b801: Worker setting wordBlockFilesBeforeVersion=0    00000000-0000-100a-806a-ff946170b801

Item 00000000-0000-100a-806a-ff946170b801: Worker setting TempDirectory=C:\Windows\TEMP\wdsrv\0a69ebd3-72c0-4ebf-9ff8-1a7ce971f01d\jo5ou1zi.40z    00000000-0000-100a-806a-ff946170b801

Item 00000000-0000-100a-806a-ff946170b801: Begin download input file 'https://webappname/sitename/foldername/filename.docx'. Opening site.    00000000-0000-100a-806a-ff946170b801

Opened site 'SPSite Url=https://webappname/sitename'. Opening web.

Opened web ''. Opening file.

File '/foldername/filename.docx' opened. Opening source file stream.

Opened source stream. Opening temp file 'C:\Windows\TEMP\wdsrv\0a69ebd3-72c0-4ebf-9ff8-1a7ce971f01d\jo5ou1zi.40z

Opened temp file. Copying stream.

Copy complete. Closing temp file.

Closing source file & stream.

Closing web.

Closing site.

End download input file.

Sending 00000000-0000-100a-806a-ff946170b801 to worker process manager; local request id = ccae6cc8-fb78-4af2-a70f-224848b25c7f    00000000-0000-100a-806a-ff946170b801

Sync job conversion starts

Request received for document 00000000-0000-100a-806a-ff946170b801, format: , request id ccae6cc8-fb78-4af2-a70f-224848b25c7f, queued requests: 14, working requests: 0   

There is an uninitialized worker that took too long to connect back. [Worker Guid: b9f6245e-477d-4ed7-b791-08d0d503d5b1]. Starting a new process

 worker process is started Exe: WordServerWorker.exe Args: /id de4a0811-677f-46fc-8287-83d63ac5c601 /convertingService net.pipe://127.0.0.1/WordServer45dd175f-3798-4740-9200-a5191f5d1185 /assembly WdsrvWorker.dll /type WACWS /IsBatchedTracing True /LogQuota 100 WorkerType: WorkerType1 Directory: c:\windows\system32\inetsrv, pid : 13228, IsSandBoxed: True, UniqueSandBoxSid: S-1-5-21-1734954099-2974945224   

Some AppServerHost process didn't connect back to AppManager

AppManager.BeginProcessRequest adding request to queue

Get wait handle

Wait on this event for Constants.ImmediateJobWaitDefault 

Sync job in progress

Sync job conversion takes too long. Don't wait anymore. Check its status later

In Progress:

Item is InProgress but has exceeded the max conversion time of 00:10:00. StartTime=XX. This item has 0 conversion attempts remaining.
 
BeginConvert complete:

AddSyncJob complete:

Proxy 'Word Automation Services': AddSyncJob 00000000-0000-100a-806a-ff946170b801 complete


Conclusion:
The Word Automation service itself is working, but the final conversion is failing.


Root Cause:

Based on our technical excavation work plus some help from online posts, we believe the root cause is a Windows bug!

Bug Impact: 
- Affects only Windows Server 2012 and Server 2012 R2 
- Affects only farms running on virtual machines.

      Details:

      - Windows will see all drives with SCSI controllers (C,D,E,.. ) as removable even though from computer management they are fixed. They will show as removable in Windows tray.
      - Windows blocks non-interactive access to all accounts trying to reach content in removable storage (regardless of permissions) except for the Local System account.

      - The Word Automation does not work as the conversion executable failing to access config file under removable storage and terminates prematurely.

So, we have 1 solution and 2 workarounds:

Solution:

KB 2822241: Windows 8 and Windows Server 2012 cumulative update: April 2013

KB 2811160

https://support.microsoft.com/en-us/help/2822241/windows-8-and-windows-server-2012-update-rollup-april-2013

https://support.microsoft.com/en-us/help/2811670/issues-when-the-audit-object-access-policy-is-enabled-on-removable-sto

VMware talked about it here: https://kb.vmware.com/s/article/2039739

Workaround #1

Manually disable the Audit object access GPO.

https://docs.microsoft.com/en-us/previous-versions/tn-archive/dd277403(v=technet.10)

I tried to manually disabled the following GPO in the APP server then restarted that machine.

Result:it did not work.

Local Computer Configuration > Windows Settings > Security Settings > Advanced Audit Policies – Local Policy Object > Object Access > Audi Removable Storage

Administrative Templates > System > Removable Storage Access

https://www.briantist.com/errors/server-2012-vmware-esxi-permissions-errors-removable-storage-auditing/   

I also tried the same thing using auditpol command. Result: it did not work.

Workaround #2

Disable the HotPlug capability on the virtual machine. Result: it worked! problem solved.

https://kb.vmware.com/s/article/1012225

FYI, querying the disks using get-volumen showed all drives as fixed so not really helpful!

Workaround #3

Downgrade the SCSI controller driver inside of the Device Manager. Not tested.

Final Result:
No solid fix from Microsoft on this bug. The only way to solve it is by disabling the HotPlug capability in virtual machine (Workaround #2 above).


Tip: I hope you let your system people know about this shortcoming in VMs.