vti not working for *some* docs

[armino]

Good morning,

Env:
Server: win2008R2, Alfresco 4.2.b community
Client: win7, Office 2010, IE9

Problem: "Edit Online" works fine for ms word documents (.docx), but failes for excel docs in the same library. I have tracked the problem down to the point where i need some help to resolve the issue. The vti handler can not resolve the file. For whatever reason "Resolved file info for X is null".

 2012-11-16 09:38:21,123  DEBUG [web.actions.VtiBinAction] [430663186@qtp-2028165209-13] Executing vtiMethod: org.alfresco.module.vti.web.fp.GetDocsMetaInfoMethod@2b529136 
[…]  
2012-11-16 09:38:21,185  DEBUG [module.vti.handler] [430663186@qtp-2028165209-13] Resolved file info for 'salesorderprocessing/documentLibrary/Reporting2/Sales Report.xlsx' is FileInfo[name=Sales Report.xlsx, isFolder=false, nodeRef=workspace://SpacesStore/2de33110-2c11-4605-aeab-c9ac03579fb4] 
[…]
 2012-11-16 09:38:21,201  DEBUG [module.vti.handler] [430663186@qtp-2028165209-13] Resolved file info for 'salesorderprocessing/documentLibrary/Reporting2/Sales%20Report.xlsx' is null
‍‍‍‍‍‍‍‍

Thanks for your input.
–Armin

Here's the full log

 2012-11-16 09:38:11,872  DEBUG [module.vti.handler] [1684523404@qtp-2028165209-12] Resolved file info for 'salesorderprocessing' is FileInfo[name=salesorderprocessing, isFolder=true, nodeRef=workspace://SpacesStore/c1e10f1a-a164-4756-b2e5-6246f0f95044]
 2012-11-16 09:38:11,887  DEBUG [module.vti.handler] [1684523404@qtp-2028165209-12] WebUrl: /alfresco/salesorderprocessing, fileUrl: 'documentLibrary/SalesInvoice/DAR05329.docx'
 2012-11-16 09:38:11,887  DEBUG [module.vti.handler] [1684523404@qtp-2028165209-12] Resolved file info for 'salesorderprocessing/documentLibrary/SalesInvoice/DAR05329.docx' is FileInfo[name=DAR05329.docx, isFolder=false, nodeRef=workspace://SpacesStore/88c90962-ca56-4780-8357-50683d03b9f8]
 2012-11-16 09:38:11,887  DEBUG [vti.web.VtiFilter] [1684523404@qtp-2028165209-12] User was authenticated successfully
 2012-11-16 09:38:11,887  DEBUG [vti.web.VtiFilter] [1684523404@qtp-2028165209-12] Return VTI answer for UNLOCK request
 2012-11-16 09:38:11,887  DEBUG [vti.web.VtiRequestDispatcher] [1684523404@qtp-2028165209-12] Dispatching request, URI path: /alfresco/salesorderprocessing/documentLibrary/SalesInvoice/DAR05329.docx
 2012-11-16 09:38:11,887  DEBUG [vti.web.VtiRequestDispatcher] [1684523404@qtp-2028165209-12] Find appropriate action by specific rules
 2012-11-16 09:38:11,887  DEBUG [vti.web.VtiRequestDispatcher] [1684523404@qtp-2028165209-12] Action found for request
 2012-11-16 09:38:11,887  DEBUG [vti.web.VtiRequestDispatcher] [1684523404@qtp-2028165209-12] Execute target action: VtiUnlockAction
 2012-11-16 09:38:20,920  DEBUG [vti.web.VtiFilter] [430663186@qtp-2028165209-13] Checking request for VTI
 2012-11-16 09:38:20,920  DEBUG [vti.web.VtiFilter] [430663186@qtp-2028165209-13] Check authentication
 2012-11-16 09:38:20,920  DEBUG [vti.web.VtiFilter] [430663186@qtp-2028165209-13] No authentication details found, requesting they authenticate
 2012-11-16 09:38:20,920  DEBUG [vti.web.VtiFilter] [430663186@qtp-2028165209-13] Checking request for VTI
 2012-11-16 09:38:20,920  DEBUG [vti.web.VtiFilter] [430663186@qtp-2028165209-13] Check authentication
 2012-11-16 09:38:20,920  DEBUG [vti.web.VtiFilter] [430663186@qtp-2028165209-13] User was authenticated successfully
 2012-11-16 09:38:20,920  DEBUG [vti.web.VtiFilter] [430663186@qtp-2028165209-13] Return VTI answer for OPTIONS request
 2012-11-16 09:38:20,920  DEBUG [vti.web.VtiRequestDispatcher] [430663186@qtp-2028165209-13] Dispatching request, URI path: /alfresco/salesorderprocessing/documentLibrary/Reporting2/
 2012-11-16 09:38:20,920  DEBUG [vti.web.VtiRequestDispatcher] [430663186@qtp-2028165209-13] Find appropriate action by specific rules
 2012-11-16 09:38:20,920  DEBUG [vti.web.VtiRequestDispatcher] [430663186@qtp-2028165209-13] Specific rule not found
 2012-11-16 09:38:20,920  DEBUG [vti.web.VtiRequestDispatcher] [430663186@qtp-2028165209-13] Find appropriate action by pattern for uri='/salesorderprocessing/documentLibrary/Reporting2/'
 2012-11-16 09:38:20,920  INFO  [vti.web.VtiRequestDispatcher] [430663186@qtp-2028165209-13] Note - no handler was found for OPTIONS to uri='/salesorderprocessing/documentLibrary/Reporting2/'
 2012-11-16 09:38:21,029  DEBUG [vti.web.VtiFilter] [430663186@qtp-2028165209-13] Checking request for VTI
 2012-11-16 09:38:21,029  DEBUG [vti.web.VtiFilter] [430663186@qtp-2028165209-13] Check authentication
 2012-11-16 09:38:21,029  DEBUG [vti.web.VtiFilter] [430663186@qtp-2028165209-13] User was authenticated successfully
 2012-11-16 09:38:21,029  DEBUG [vti.web.VtiFilter] [430663186@qtp-2028165209-13] Return VTI answer for HEAD request
 2012-11-16 09:38:21,029  DEBUG [vti.web.VtiRequestDispatcher] [430663186@qtp-2028165209-13] Dispatching request, URI path: /_vti_inf.html
 2012-11-16 09:38:21,029  DEBUG [vti.web.VtiRequestDispatcher] [430663186@qtp-2028165209-13] Find appropriate action by specific rules
 2012-11-16 09:38:21,029  DEBUG [vti.web.VtiRequestDispatcher] [430663186@qtp-2028165209-13] Specific rule not found
 2012-11-16 09:38:21,029  DEBUG [vti.web.VtiRequestDispatcher] [430663186@qtp-2028165209-13] Find appropriate action by pattern for uri='/_vti_inf.html'
 2012-11-16 09:38:21,029  DEBUG [vti.web.VtiRequestDispatcher] [430663186@qtp-2028165209-13] Action found for request
 2012-11-16 09:38:21,029  DEBUG [vti.web.VtiRequestDispatcher] [430663186@qtp-2028165209-13] Execute target action: VtiInfAction
 2012-11-16 09:38:21,029  DEBUG [vti.web.VtiFilter] [430663186@qtp-2028165209-13] Checking request for VTI
 2012-11-16 09:38:21,029  DEBUG [vti.web.VtiFilter] [430663186@qtp-2028165209-13] Check authentication
 2012-11-16 09:38:21,029  DEBUG [vti.web.VtiFilter] [430663186@qtp-2028165209-13] User was authenticated successfully
 2012-11-16 09:38:21,029  DEBUG [vti.web.VtiRequestDispatcher] [430663186@qtp-2028165209-13] Dispatching request, URI path: /_vti_bin/shtml.dll/_vti_rpc
 2012-11-16 09:38:21,029  DEBUG [vti.web.VtiRequestDispatcher] [430663186@qtp-2028165209-13] Find appropriate action by specific rules
 2012-11-16 09:38:21,029  DEBUG [vti.web.VtiRequestDispatcher] [430663186@qtp-2028165209-13] Specific rule not found
 2012-11-16 09:38:21,029  DEBUG [vti.web.VtiRequestDispatcher] [430663186@qtp-2028165209-13] Find appropriate action by pattern for uri='/_vti_bin/shtml.dll/_vti_rpc'
 2012-11-16 09:38:21,029  DEBUG [vti.web.VtiRequestDispatcher] [430663186@qtp-2028165209-13] Action found for request
 2012-11-16 09:38:21,029  DEBUG [vti.web.VtiRequestDispatcher] [430663186@qtp-2028165209-13] Execute target action: VtiBinAction
 2012-11-16 09:38:21,029  DEBUG [web.actions.VtiBinAction] [430663186@qtp-2028165209-13] Executing vtiMethod: org.alfresco.module.vti.web.fp.ServerVersionMethod@731ba511
 2012-11-16 09:38:21,029  DEBUG [vti.web.VtiFilter] [430663186@qtp-2028165209-13] Checking request for VTI
 2012-11-16 09:38:21,029  DEBUG [vti.web.VtiFilter] [430663186@qtp-2028165209-13] Check authentication
 2012-11-16 09:38:21,045  DEBUG [vti.web.VtiFilter] [430663186@qtp-2028165209-13] User was authenticated successfully
 2012-11-16 09:38:21,045  DEBUG [vti.web.VtiRequestDispatcher] [430663186@qtp-2028165209-13] Dispatching request, URI path: /_vti_bin/shtml.dll/_vti_rpc
 2012-11-16 09:38:21,045  DEBUG [vti.web.VtiRequestDispatcher] [430663186@qtp-2028165209-13] Find appropriate action by specific rules
 2012-11-16 09:38:21,045  DEBUG [vti.web.VtiRequestDispatcher] [430663186@qtp-2028165209-13] Specific rule not found
 2012-11-16 09:38:21,045  DEBUG [vti.web.VtiRequestDispatcher] [430663186@qtp-2028165209-13] Find appropriate action by pattern for uri='/_vti_bin/shtml.dll/_vti_rpc'
 2012-11-16 09:38:21,045  DEBUG [vti.web.VtiRequestDispatcher] [430663186@qtp-2028165209-13] Action found for request
 2012-11-16 09:38:21,045  DEBUG [vti.web.VtiRequestDispatcher] [430663186@qtp-2028165209-13] Execute target action: VtiBinAction
 2012-11-16 09:38:21,045  DEBUG [web.actions.VtiBinAction] [430663186@qtp-2028165209-13] Executing vtiMethod: org.alfresco.module.vti.web.fp.UrlToWebUrlMethod@5b77402c
 2012-11-16 09:38:21,045  DEBUG [module.vti.handler] [430663186@qtp-2028165209-13] Resolved file info for 'salesorderprocessing/documentLibrary/Reporting2/Sales Report.xlsx' is FileInfo[name=Sales Report.xlsx, isFolder=false, nodeRef=workspace://SpacesStore/2de33110-2c11-4605-aeab-c9ac03579fb4]
 2012-11-16 09:38:21,045  DEBUG [module.vti.handler] [430663186@qtp-2028165209-13] Resolved file info for 'salesorderprocessing/documentLibrary/Reporting2' is FileInfo[name=Reporting2, isFolder=true, nodeRef=workspace://SpacesStore/51938607-9e07-414c-ba6a-c9d2ef5de8fb]
 2012-11-16 09:38:21,045  DEBUG [module.vti.handler] [430663186@qtp-2028165209-13] Resolved file info for 'salesorderprocessing/documentLibrary' is FileInfo[name=documentLibrary, isFolder=true, nodeRef=workspace://SpacesStore/504cab49-cf1b-4507-9cde-f6d9ea12f527]
 2012-11-16 09:38:21,045  DEBUG [module.vti.handler] [430663186@qtp-2028165209-13] Resolved file info for 'salesorderprocessing' is FileInfo[name=salesorderprocessing, isFolder=true, nodeRef=workspace://SpacesStore/c1e10f1a-a164-4756-b2e5-6246f0f95044]
 2012-11-16 09:38:21,045  DEBUG [module.vti.handler] [430663186@qtp-2028165209-13] WebUrl: /alfresco/salesorderprocessing, fileUrl: 'documentLibrary/Reporting2/Sales Report.xlsx'
 2012-11-16 09:38:21,060  DEBUG [vti.web.VtiFilter] [430663186@qtp-2028165209-13] Checking request for VTI
 2012-11-16 09:38:21,060  DEBUG [vti.web.VtiFilter] [430663186@qtp-2028165209-13] Check authentication
 2012-11-16 09:38:21,092  DEBUG [module.vti.handler] [430663186@qtp-2028165209-13] Resolved file info for 'salesorderprocessing/_vti_bin/_vti_aut/author.dll' is null
 2012-11-16 09:38:21,092  DEBUG [module.vti.handler] [430663186@qtp-2028165209-13] Resolved file info for 'salesorderprocessing/_vti_bin/_vti_aut' is null
 2012-11-16 09:38:21,092  DEBUG [module.vti.handler] [430663186@qtp-2028165209-13] Resolved file info for 'salesorderprocessing/_vti_bin' is null
 2012-11-16 09:38:21,092  DEBUG [module.vti.handler] [430663186@qtp-2028165209-13] Resolved file info for 'salesorderprocessing' is FileInfo[name=salesorderprocessing, isFolder=true, nodeRef=workspace://SpacesStore/c1e10f1a-a164-4756-b2e5-6246f0f95044]
 2012-11-16 09:38:21,107  DEBUG [module.vti.handler] [430663186@qtp-2028165209-13] WebUrl: /alfresco/salesorderprocessing, fileUrl: '_vti_bin/_vti_aut/author.dll'
 2012-11-16 09:38:21,107  DEBUG [vti.web.VtiFilter] [430663186@qtp-2028165209-13] User was authenticated successfully
 2012-11-16 09:38:21,107  DEBUG [vti.web.VtiRequestDispatcher] [430663186@qtp-2028165209-13] Dispatching request, URI path: /alfresco/salesorderprocessing/_vti_bin/_vti_aut/author.dll
 2012-11-16 09:38:21,107  DEBUG [vti.web.VtiRequestDispatcher] [430663186@qtp-2028165209-13] Find appropriate action by specific rules
 2012-11-16 09:38:21,107  DEBUG [vti.web.VtiRequestDispatcher] [430663186@qtp-2028165209-13] Specific rule not found
 2012-11-16 09:38:21,107  DEBUG [vti.web.VtiRequestDispatcher] [430663186@qtp-2028165209-13] Find appropriate action by pattern for uri='/salesorderprocessing/_vti_bin/_vti_aut/author.dll'
 2012-11-16 09:38:21,107  DEBUG [vti.web.VtiRequestDispatcher] [430663186@qtp-2028165209-13] Action found for request
 2012-11-16 09:38:21,107  DEBUG [vti.web.VtiRequestDispatcher] [430663186@qtp-2028165209-13] Execute target action: VtiBinAction
 2012-11-16 09:38:21,107  DEBUG [web.actions.VtiBinAction] [430663186@qtp-2028165209-13] Executing vtiMethod: org.alfresco.module.vti.web.fp.OpenServiceMethod@1abac4b0
 2012-11-16 09:38:21,107  DEBUG [vti.web.VtiFilter] [430663186@qtp-2028165209-13] Checking request for VTI
 2012-11-16 09:38:21,107  DEBUG [vti.web.VtiFilter] [430663186@qtp-2028165209-13] Check authentication
 2012-11-16 09:38:21,107  DEBUG [module.vti.handler] [430663186@qtp-2028165209-13] Resolved file info for 'salesorderprocessing/_vti_bin/_vti_aut/author.dll' is null
 2012-11-16 09:38:21,123  DEBUG [module.vti.handler] [430663186@qtp-2028165209-13] Resolved file info for 'salesorderprocessing/_vti_bin/_vti_aut' is null
 2012-11-16 09:38:21,123  DEBUG [module.vti.handler] [430663186@qtp-2028165209-13] Resolved file info for 'salesorderprocessing/_vti_bin' is null
 2012-11-16 09:38:21,123  DEBUG [module.vti.handler] [430663186@qtp-2028165209-13] Resolved file info for 'salesorderprocessing' is FileInfo[name=salesorderprocessing, isFolder=true, nodeRef=workspace://SpacesStore/c1e10f1a-a164-4756-b2e5-6246f0f95044]
 2012-11-16 09:38:21,123  DEBUG [module.vti.handler] [430663186@qtp-2028165209-13] WebUrl: /alfresco/salesorderprocessing, fileUrl: '_vti_bin/_vti_aut/author.dll'
 2012-11-16 09:38:21,123  DEBUG [vti.web.VtiFilter] [430663186@qtp-2028165209-13] User was authenticated successfully
 2012-11-16 09:38:21,123  DEBUG [vti.web.VtiRequestDispatcher] [430663186@qtp-2028165209-13] Dispatching request, URI path: /alfresco/salesorderprocessing/_vti_bin/_vti_aut/author.dll
 2012-11-16 09:38:21,123  DEBUG [vti.web.VtiRequestDispatcher] [430663186@qtp-2028165209-13] Find appropriate action by specific rules
 2012-11-16 09:38:21,123  DEBUG [vti.web.VtiRequestDispatcher] [430663186@qtp-2028165209-13] Specific rule not found
 2012-11-16 09:38:21,123  DEBUG [vti.web.VtiRequestDispatcher] [430663186@qtp-2028165209-13] Find appropriate action by pattern for uri='/salesorderprocessing/_vti_bin/_vti_aut/author.dll'
 2012-11-16 09:38:21,123  DEBUG [vti.web.VtiRequestDispatcher] [430663186@qtp-2028165209-13] Action found for request
 2012-11-16 09:38:21,123  DEBUG [vti.web.VtiRequestDispatcher] [430663186@qtp-2028165209-13] Execute target action: VtiBinAction
 2012-11-16 09:38:21,123  DEBUG [web.actions.VtiBinAction] [430663186@qtp-2028165209-13] Executing vtiMethod: org.alfresco.module.vti.web.fp.GetDocsMetaInfoMethod@2b529136
 2012-11-16 09:38:21,123  DEBUG [module.vti.handler] [430663186@qtp-2028165209-13] Resolved file info for 'salesorderprocessing/documentLibrary/Reporting2/Sales Report.xlsx' is FileInfo[name=Sales Report.xlsx, isFolder=false, nodeRef=workspace://SpacesStore/2de33110-2c11-4605-aeab-c9ac03579fb4]
 2012-11-16 09:38:21,138  DEBUG [module.vti.handler] [430663186@qtp-2028165209-13] Resolved file info for 'salesorderprocessing/documentLibrary' is FileInfo[name=documentLibrary, isFolder=true, nodeRef=workspace://SpacesStore/504cab49-cf1b-4507-9cde-f6d9ea12f527]
 2012-11-16 09:38:21,185  DEBUG [vti.web.VtiFilter] [430663186@qtp-2028165209-13] Checking request for VTI
 2012-11-16 09:38:21,185  DEBUG [vti.web.VtiFilter] [430663186@qtp-2028165209-13] Check authentication
 2012-11-16 09:38:21,185  DEBUG [module.vti.handler] [430663186@qtp-2028165209-13] Resolved file info for 'salesorderprocessing/documentLibrary/Reporting2/Sales Report.xlsx' is FileInfo[name=Sales Report.xlsx, isFolder=false, nodeRef=workspace://SpacesStore/2de33110-2c11-4605-aeab-c9ac03579fb4]
 2012-11-16 09:38:21,201  DEBUG [module.vti.handler] [430663186@qtp-2028165209-13] Resolved file info for 'salesorderprocessing/documentLibrary/Reporting2' is FileInfo[name=Reporting2, isFolder=true, nodeRef=workspace://SpacesStore/51938607-9e07-414c-ba6a-c9d2ef5de8fb]
 2012-11-16 09:38:21,201  DEBUG [module.vti.handler] [430663186@qtp-2028165209-13] Resolved file info for 'salesorderprocessing/documentLibrary' is FileInfo[name=documentLibrary, isFolder=true, nodeRef=workspace://SpacesStore/504cab49-cf1b-4507-9cde-f6d9ea12f527]
 2012-11-16 09:38:21,201  DEBUG [module.vti.handler] [430663186@qtp-2028165209-13] Resolved file info for 'salesorderprocessing' is FileInfo[name=salesorderprocessing, isFolder=true, nodeRef=workspace://SpacesStore/c1e10f1a-a164-4756-b2e5-6246f0f95044]
 2012-11-16 09:38:21,201  DEBUG [module.vti.handler] [430663186@qtp-2028165209-13] WebUrl: /alfresco/salesorderprocessing, fileUrl: 'documentLibrary/Reporting2/Sales%20Report.xlsx'
 2012-11-16 09:38:21,201  DEBUG [module.vti.handler] [430663186@qtp-2028165209-13] Resolved file info for 'salesorderprocessing/documentLibrary/Reporting2/Sales%20Report.xlsx' is null
 2012-11-16 09:38:21,201  DEBUG [vti.web.VtiFilter] [430663186@qtp-2028165209-13] No authentication details found, requesting they authenticate
 2012-11-16 09:38:21,201  DEBUG [vti.web.VtiFilter] [430663186@qtp-2028165209-13] Checking request for VTI
 2012-11-16 09:38:21,216  DEBUG [vti.web.VtiFilter] [430663186@qtp-2028165209-13] Check authentication
 2012-11-16 09:38:21,216  DEBUG [module.vti.handler] [430663186@qtp-2028165209-13] Resolved file info for 'salesorderprocessing/documentLibrary/Reporting2/Sales Report.xlsx' is FileInfo[name=Sales Report.xlsx, isFolder=false, nodeRef=workspace://SpacesStore/2de33110-2c11-4605-aeab-c9ac03579fb4]
 2012-11-16 09:38:21,216  DEBUG [module.vti.handler] [430663186@qtp-2028165209-13] Resolved file info for 'salesorderprocessing/documentLibrary/Reporting2' is FileInfo[name=Reporting2, isFolder=true, nodeRef=workspace://SpacesStore/51938607-9e07-414c-ba6a-c9d2ef5de8fb]
 2012-11-16 09:38:21,216  DEBUG [module.vti.handler] [430663186@qtp-2028165209-13] Resolved file info for 'salesorderprocessing/documentLibrary' is FileInfo[name=documentLibrary, isFolder=true, nodeRef=workspace://SpacesStore/504cab49-cf1b-4507-9cde-f6d9ea12f527]
 2012-11-16 09:38:21,232  DEBUG [module.vti.handler] [430663186@qtp-2028165209-13] Resolved file info for 'salesorderprocessing' is FileInfo[name=salesorderprocessing, isFolder=true, nodeRef=workspace://SpacesStore/c1e10f1a-a164-4756-b2e5-6246f0f95044]
 2012-11-16 09:38:21,232  DEBUG [module.vti.handler] [430663186@qtp-2028165209-13] WebUrl: /alfresco/salesorderprocessing, fileUrl: 'documentLibrary/Reporting2/Sales%20Report.xlsx'
 2012-11-16 09:38:21,232  DEBUG [module.vti.handler] [430663186@qtp-2028165209-13] Resolved file info for 'salesorderprocessing/documentLibrary/Reporting2/Sales%20Report.xlsx' is null
 2012-11-16 09:38:21,232  DEBUG [vti.web.VtiFilter] [430663186@qtp-2028165209-13] No authentication details found, requesting they authenticate
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 

‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍

[armino]

It appears the problem is a copy of

https://issues.alfresco.com/jira/browse/ALF-16532

I could reproduce the erratic behavior on the windows and linux platform both running 4.2.b

Applying the share point protocol from the 4.2.c nightly build resolved it.

Best wishes,
Armin