Office Web Apps – Word Viewing Service Error

All of a sudden, we started having issues with our Office Web Apps install for a set of users.  No reason, no changes, just some users can't use OWA to VIEW files (they can however edit the files in the browser).  The service account for the application pool and the word viewing app pool both have dbo on the content database in question.

Here's the errors:

User:

Word Web App cannot open this document for viewing because of an unexpected error.  To view this document, open it in Microsoft Word.

WFE:

 05/23/2012 07:56:55.17  w3wp.exe (0x32CC)                        0x310C Office Web Apps                Office Viewing Architecture    dg2s Medium   RequestDispatcher: response received for document F4813f0a0691d4d61a109e9ab86a17815m4d776f4fd83844328210cf1c84e667cbm06ebaf2e1684459c9c00819543a2a08em from http://servername:32843/69c32f311e164e8184803a179b32d194/Conversion.svc. d3e88a2a-977b-48df-a70a-4765c4ff1ac9
05/23/2012 07:56:55.19  w3wp.exe (0x32CC)                        0x310C Office Web Apps                Office Viewing Architecture    b4vn Medium   Conversion response received: CantFindSourceDocument d3e88a2a-977b-48df-a70a-4765c4ff1ac9
05/23/2012 07:56:55.19  w3wp.exe (0x32CC)                        0x310C Office Web Apps                Office Viewing Architecture    b4vi Verbose  DocumentInfoCache.RemoveDocumentInfo: docId=d=F4813f0a0691d4d61a109e9ab86a17815m4d776f4fd83844328210cf1c84e667cbm06ebaf2e1684459c9c00819543a2a08em&z=06EBAF2E-1684-459C-9C00-819543A2A08E1, outputFormat=_v00000000-0000-0000-0000-000000000202 d3e88a2a-977b-48df-a70a-4765c4ff1ac9
05/23/2012 07:56:55.19  w3wp.exe (0x32CC)                        0x310C Office Web Apps                Office Viewing Architecture    vjza Medium   Librarian.OnConversionResponseReceived(F4813f0a0691d4d61a109e9ab86a17815m4d776f4fd83844328210cf1c84e667cbm06ebaf2e1684459c9c00819543a2a08em, Png, docdata.xml) – Response=CantFindSourceDocument, Data=NO d3e88a2a-977b-48df-a70a-4765c4ff1ac9
05/23/2012 07:56:55.20  w3wp.exe (0x32CC)                        0x310C Office Web Apps                Office Viewing Architecture    vjzo Medium   Librarian.SetCompleted(F4813f0a0691d4d61a109e9ab86a17815m4d776f4fd83844328210cf1c84e667cbm06ebaf2e1684459c9c00819543a2a08em, Png, docdata.xml) – status = ConversionError d3e88a2a-977b-48df-a70a-4765c4ff1ac9

APP:

05/23/2012 07:56:55.57  w3wp.exe (0x1330)                        0x0B6C Office Web Apps                Office Viewing Architecture    bv6l Medium   DownloadManager: Starting download for document F4813f0a0691d4d61a109e9ab86a17815m4d776f4fd83844328210cf1c84e667cbm06ebaf2e1684459c9c00819543a2a08em. d3e88a2a-977b-48df-a70a-4765c4ff1ac9
05/23/2012 07:56:55.57  w3wp.exe (0x1330)                        0x0B6C Office Web Apps                Office Performance Tracing     dcw3 Verbose  PerfCounterAverageTimer started: WssStorageReadTime d3e88a2a-977b-48df-a70a-4765c4ff1ac9
05/23/2012 07:56:55.57  w3wp.exe (0x1330)                        0x0B6C SharePoint Foundation          General                        6t8j Verbose  Site lookup by id found the typical site /training. d3e88a2a-977b-48df-a70a-4765c4ff1ac9
05/23/2012 07:56:55.57  w3wp.exe (0x1330)                        0x0B6C SharePoint Foundation          General                        8kh7 High     Cannot complete this action.  Please try again. d3e88a2a-977b-48df-a70a-4765c4ff1ac9
05/23/2012 07:56:55.58  w3wp.exe (0x1330)                        0x0B6C SharePoint Foundation          General                        8kh7 High     Stack trace: onetutil.dll: (unresolved symbol, module offset=00000000000A2551) at 0x000007FEF0142551 onetutil.dll: (unresolved symbol, module offset=00000000000A3711) at 0x000007FEF0143711 owssvr.dll: (unresolved symbol, module offset=0000000000009212) at 0x000007FEF0399212 owssvr.dll: (unresolved symbol, module offset=0000000000044378) at 0x000007FEF03D4378 mscorwks.dll: (unresolved symbol, module offset=00000000002CB6D7) at 0x000007FEF9BFB6D7 Microsoft.SharePoint.Library.ni.dll: (unresolved symbol, module offset=00000000000E5128) at 0x000007FEF2D85128 Microsoft.SharePoint.ni.dll: (unresolved symbol, module offset=0000000001AB43D0) at 0x000007FEE0AA43D0 Microsoft.SharePoint.ni.dll: (unresolved symbol, module offset=0000000001AA811D) at 0x000007FEE0A9811D Microsoft.SharePoint.ni.dll: (unre… d3e88a2a-977b-48df-a70a-4765c4ff1ac9
05/23/2012 07:56:55.58* w3wp.exe (0x1330)                        0x0B6C SharePoint Foundation          General                        8kh7 High     …solved symbol, module offset=0000000001AADC71) at 0x000007FEE0A9DC71 Microsoft.SharePoint.ni.dll: (unresolved symbol, module offset=0000000001AA2A25) at 0x000007FEE0A92A25 Microsoft.SharePoint.ni.dll: (unresolved symbol, module offset=0000000001AA4717) at 0x000007FEE0A94717 Microsoft.SharePoint.ni.dll: (unresolved symbol, module offset=0000000001AA46A2) at 0x000007FEE0A946A2  d3e88a2a-977b-48df-a70a-4765c4ff1ac9
05/23/2012 07:56:55.58  w3wp.exe (0x1330)            &nbs
p;           0x0B6C Office Web Apps                Office Viewing Architecture    ekp1 Medium   No SPFile found for Id 06ebaf2e-1684-459c-9c00-819543a2a08e d3e88a2a-977b-48df-a70a-4765c4ff1ac9
05/23/2012 07:56:55.58  w3wp.exe (0x1330)                        0x0B6C Office Web Apps                Office Viewing Architecture    ekp3 Medium   SharepointReaderAsync: No SPFile provided d3e88a2a-977b-48df-a70a-4765c4ff1ac9
05/23/2012 07:56:55.58  w3wp.exe (0x1330)                        0x0B6C Office Web Apps                Office Performance Tracing     a495 Verbose  PerfCounterAverageTimer stopped: WssStorageReadTime, elapsed time = 20 milliseconds d3e88a2a-977b-48df-a70a-4765c4ff1ac9
05/23/2012 07:56:55.58  w3wp.exe (0x1330)                        0x0B6C Office Web Apps                Office Viewing Architecture    bv6p Unexpected Exception thrown downloading file C:WindowsTEMPwaccache69c32f31-1e16-4e81-8480-3a179b32d194domainuserca171873-6de3-4dd4-abef-09d23996d26coutput.docx: System.ArgumentException: SharepointReaderAsync: no SPFile     at Microsoft.Office.Web.Environment.Sharepoint.SharepointReaderAsync.End()     at Microsoft.Office.Web.Conversion.Framework.DownloadManager.OnFileReadComplete(IAsyncResult ar) d3e88a2a-977b-48df-a70a-4765c4ff1ac9
05/23/2012 07:56:55.58  w3wp.exe (0x1330)                        0x0B6C Office Web Apps                Office Viewing Architecture    fvj9 Unexpected DownloadManager: Download FAILED for document F4813f0a0691d4d61a109e9ab86a17815m4d776f4fd83844328210cf1c84e667cbm06ebaf2e1684459c9c00819543a2a08em; Time spent: 24ms. d3e88a2a-977b-48df-a70a-4765c4ff1ac9

The only possible hints lie in the users access (this says it is request view and edit access but the user doesn't have it):

05/23/2012 07:56:54.20  w3wp.exe (0x32CC)                        0x2B94 SharePoint Foundation          General                        ewn8 Verbose  OriginalPermissionMask check failed. asking for 0x00000005, have 0xB008431041 9806faaf-ad37-406f-9164-5705a9aca938

You'll also find several errors about configuration settings missing for the Word Viewing settings:

05/23/2012 07:56:54.30  w3wp.exe (0x32CC)                        0x2B94 Office Web Apps                Office Web Apps Configuration  bbw9 Verbose  Trying to get setting C2ROFFERENABLED 9806faaf-ad37-406f-9164-5705a9aca938
05/23/2012 07:56:54.30  w3wp.exe (0x32CC)                        0x2B94 Office Web Apps                Office Web Apps Configuration  bbx0 Verbose  Tried to obtain setting C2ROFFERENABLED but it does not exist in the list of known settings for this environment. 9806faaf-ad37-406f-9164-5705a9aca938
05/23/2012 07:56:54.30  w3wp.exe (0x32CC)                        0x2B94 Office Web Apps                Office Web Apps Configuration  bbw9 Verbose  Trying to get setting WLSIAOFFERENABLED 9806faaf-ad37-406f-9164-5705a9aca938
05/23/2012 07:56:54.30  w3wp.exe (0x32CC)                        0x2B94 Office Web Apps                Office Web Apps Configuration  bbx0 Verbose  Tried to obtain setting WLSIAOFFERENABLED but it does not exist in the list of known settings for this environment. 9806faaf-ad37-406f-9164-5705a9aca938
05/23/2012 07:56:54.31  w3wp.exe (0x32CC)                        0x2B94 Office Web Apps                Office Web Apps Configuration  bbw9 Verbose  Trying to get setting USEPARENTHELPFUNCTION 9806faaf-ad37-406f-9164-5705a9aca938
05/23/2012 07:56:54.31  w3wp.exe (0x32CC)                        0x2B94 Office Web Apps                Office Web Apps Configuration  bbx0 Verbose  Tried to obtain setting USEPARENTHELPFUNCTION but it does not exist in the list of known settings for this environment. 9806faaf-ad37-406f-9164-5705a9aca938
05/23/2012 07:56:54.31  w3wp.exe (0x32CC)                        0x2B94 Office Web Apps                Office Web Apps Configuration  bbw9 Verbose  Trying to get setting SHOWFEEDBACKLINK 9806faaf-ad37-406f-9164-5705a9aca938
05/23/2012 07:56:54.31  w3wp.exe (0x32CC)                        0x2B94 Office Web Apps                Office Web Apps Configuration  bbx0 Verbose  Tried to obtain setting SHOWFEEDBACKLINK but it does not exist in the list of known settings for this environment. 9806faaf-ad37-406f-9164-5705a9aca938
05/23/2012 07:56:54.33  w3wp.exe (0x32CC)                        0x2B94 Office Web Apps                Office Web Apps Configuration  bbw9 Verbose  Trying to get setting HIDETITLE 9806faaf-ad37-406f-9164-5705a9aca938
05/23/2012 07:56:54.33  w3wp.exe (0x32CC)                        0x2B94 Office Web Apps     
           Office Web Apps Configuration  bbx0 Verbose  Tried to obtain setting HIDETITLE but it does not exist in the list of known settings for this environment. 9806faaf-ad37-406f-9164-5705a9aca938
05/23/2012 07:56:54.33  w3wp.exe (0x32CC)                        0x2B94 Office Web Apps                Office Web Apps Configuration  bbw9 Verbose  Trying to get setting MACOFFICETRIALOFFERENABLED 9806faaf-ad37-406f-9164-5705a9aca938
05/23/2012 07:56:54.33  w3wp.exe (0x32CC)                        0x2B94 Office Web Apps                Office Web Apps Configuration  bbx0 Verbose  Tried to obtain setting MACOFFICETRIALOFFERENABLED but it does not exist in the list of known settings for this environment. 9806faaf-ad37-406f-9164-5705a9aca938
05/23/2012 07:56:54.33  w3wp.exe (0x32CC)                        0x2B94 Office Web Apps                Office Web Apps Configuration  bbw9 Verbose  Trying to get setting TRIMOICBUTTONSIFUNAVAILABLE 9806faaf-ad37-406f-9164-5705a9aca938
05/23/2012 07:56:54.33  w3wp.exe (0x32CC)                        0x2B94 Office Web Apps                Office Web Apps Configuration  bbx0 Verbose  Tried to obtain setting TRIMOICBUTTONSIFUNAVAILABLE but it does not exist in the list of known settings for this environment. 9806faaf-ad37-406f-9164-5705a9aca938
05/23/2012 07:56:54.33  w3wp.exe (0x32CC)                        0x2B94 Office Web Apps                Office Web Apps Configuration  bbw9 Verbose  Trying to get setting WORDWEBAPPSHORTRESOURCENAME 9806faaf-ad37-406f-9164-5705a9aca938
05/23/2012 07:56:54.33  w3wp.exe (0x32CC)                        0x2B94 Office Web Apps                Office Web Apps Configuration  bbw9 Verbose  Trying to get setting WORDWEBAPPFULLRESOURCENAME 9806faaf-ad37-406f-9164-5705a9aca938

What have I done so far?  Here's the things I have tried: 

  1. I created a new Word Viewing Service and set it as the default service application.  Had the user retry…the documents still didn't display in OWA and I still get all the wonderful OWA settings are missing messages (so the messages can be ignored) – NO GO
  2. I gave the user contribute access, had them re-try…still didn't display in OWA, but at least a new button showed up on the error that lets them "Open in Word" (realized this happens after the second attempt to open the file) – NO GO
  3. Last ditch effort, added the app pool for the OWA conversion service to the local WSS_ADMIN_WPG…NO GO.
  4. Made the user a site collection admin – NO GO  

Weird that it only applies to a small set of users.  It shouldn't matter that they just have View Only rights to the file, it should open in OWA…again editing works just fine…

Sooo…how did I fix this?  I went to the handy SQL Profiler tool and watched the SQL traffic.  I re-run all the queries and looked at all the results sets that were returned.  I opened the OWA dlls in Reflecter and explored every method call.  I found the "no SPFile" returned set of code, everything looks file, but, it is the hint that I was looking for.  Stepping back, one should ask…why is the file not being returned?  It is there, but…it isn't?  In looking at the result sets, I found something interesting.  Once upon a time, users had enabled the DocumentID feature of sharepoint.  This assigned document ids to some of the documents.  They also are using this tool called "CopyPaste".  When copying a record from one site collection to another, the document ID values were being replicated to the new location and metadata of the files.  When OWA makes the call to get the file, it is going through the SharePoint APIs and in this case, the document ID is wrong and the site that used to hold the file is gone (or in some cases not accessible by the user because we removed their permissions)!  Document IDs suck and this is just another reason to use my SharePoint Durable Urls tool (http://www.sharepointdurableurls.com). That means…if you hit the document id link for the file, you get simple html that says "File Not Found".  BINGO!  Now…how to remove the DocumentID residual?  Here's what I did:

foreach($li in $list.items)
{
$docid = $li["Document ID"]

if ($docid)
{
"Found doc id in " + $li["Name"]
"ID is: $docid"

$li.file.checkout()
$li["Document ID"] = ""
$li.update()
$li.file.checkin("Removed Document ID")
}
}

Yet another case of the code making one call (View is using the DocumentID redirect) in one instance and another in another instance (Editing does not use the DocumentID redirect).  Very annoying.

Enjoy!
Chris

Follow me on twitter: @givenscj

Check out the previous blog post:
https://blogs.architectingconnectedsystems.com/blogs/cjg/archive/2012/05/18/Announcing-_2D00_-ACS-Rebate-and-Charity-Event.aspx