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.
- 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.
- 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
VMware talked about it here: https://kb.vmware.com/s/article/2039739
Workaround #1
Manually disable the Audit object access GPO.
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
Workaround #2
Disable the HotPlug capability on the virtual machine. Result: it worked! problem solved.
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.