• Facebook
  • RSS Feed
  • Instagram
  • LinkedIn
  • Twitter
May 272013
 

DSCN4897Retrieving an item in Enterprise Vault’s Outlook Add-in is of course one of the most common activities that take place day-in and day-out in an archived email environment. It is interesting to know what it actually involves, so let’s take a look at the process undertaken with the Enterprise Vault 10.0.3 Outlook Addin ….

When logging is set to the default level of ‘Information’ then nothing is logged in the Outlook Add-in client log file. On the Enterprise Vault server, the IIS logs will show the retrieval was performed (and of course DTRACE can prove it too):

2013-04-05 23:59:59 192.168.145.167 GET /EnterpriseVault/download.asp VaultID=18A5257C941B9A84F8A6CA597937F3B611110000evsql.ev.local&SaveSetID=201304287177491~201304081913380000~Z~D006154F7F2EA1F13C9DC57A4D6D4C81&FormatType=Unicode&Client=EV10.0.3.1090-Outlook14&Format=MUD&AttachmentID=0 80 EV\rob1 192.168.145.18 EnterpriseVaultOutlookExt-V10.0.3.1090 200 0 0 164

With minimum tracing enabled then the Enterprise Vault Outlook Add-in shows some information in the client trace:

28/04/2013 19:37:02.159[3976][M]: Acquiring lock: 0x6EAB7ADC
28/04/2013 19:37:02.159[3976][M]: Acquired lock: 0x6EAB7ADC
28/04/2013 19:37:02.159[3976][M]: Released lock: 0x6EAB7ADC
28/04/2013 19:37:02.275[3976][M]: Have unadvised on ItemEvents_10
28/04/2013 19:37:02.783[3976][M]: Have unadvised on ItemEvents_10
28/04/2013 19:37:02.900[3976][M]: Connections now on Desktop object: 3
28/04/2013 19:37:02.900[3976][M]: Desktop Setting: ForwardOriginalItem
28/04/2013 19:37:02.901[3976][M]: No Value
28/04/2013 19:37:02.901[3976][M]: Desktop Setting: ReplyToOriginalItem
28/04/2013 19:37:02.901[3976][M]: No Value
28/04/2013 19:37:02.902[3976][M]: Connections left on Desktop object: 2
28/04/2013 19:37:02.902[3976][M]: Desktop Setting: DefaultDoubleClickView
28/04/2013 19:37:02.902[3976][M]: Value: 0
28/04/2013 19:37:02.902[3976][M]: Desktop Setting: WebAppURL[evsql.ev.local]
28/04/2013 19:37:02.903[3976][M]: No Value
28/04/2013 19:37:02.903[3976][M]: Desktop Setting: DefaultDoubleClickView
28/04/2013 19:37:02.903[3976][M]: Value: 0
28/04/2013 19:37:02.903[3976][M]: Downloading from: http://evsql.ev.local/EnterpriseVault/download.asp?VaultID=18A5257C941B9A84F8A6CA597937F3B611110000evsql.ev.local&SaveSetID=201304287177491~201304081913380000~Z~D006154F7F2EA1F13C9DC57A4D6D4C81&FormatType=Unicode&Client=EV10.0.3.1090-Outlook14&Format=MUD&AttachmentID=0
28/04/2013 19:37:02.903[3976][M]: ::CInternetReconnect - refCount : 1
28/04/2013 19:37:02.904[3976][M]: CThreadManager::Add thread THID=372
28/04/2013 19:37:02.913[3976][M]: Acquiring lock: 0x6EAB7ADC
28/04/2013 19:37:02.913[3976][M]: Acquired lock: 0x6EAB7ADC
28/04/2013 19:37:02.914[3976][M]: Released lock: 0x6EAB7ADC
28/04/2013 19:37:02.918[ 372][M]: Downloading: http://evsql.ev.local/EnterpriseVault/download.asp?VaultID=18A5257C941B9A84F8A6CA597937F3B611110000evsql.ev.local&SaveSetID=201304287177491~201304081913380000~Z~D006154F7F2EA1F13C9DC57A4D6D4C81&FormatType=Unicode&Client=EV10.0.3.1090-Outlook14&Format=MUD&AttachmentID=0
28/04/2013 19:37:02.919[ 372][M]: CThreadManager::Add thread THID=3308
28/04/2013 19:37:02.919[ 372][M]: Desktop Setting: RESTRICTPOLICYLOOKUP
28/04/2013 19:37:02.920[ 372][M]: No Value
28/04/2013 19:37:02.920[ 372][M]: Desktop Setting: DOWNLOADSHORTCUTHIDEPROGRESS
28/04/2013 19:37:02.920[ 372][M]: No Value
28/04/2013 19:37:02.920[ 372][M]: DOWNLOADSHORTCUTHIDEPROGRESS = 1 [default]
28/04/2013 19:37:02.920[ 372][M]: Download progress dialog delay set to 1 seconds.
28/04/2013 19:37:02.924[3308][M]: Desktop Setting: RESTRICTPOLICYLOOKUP
28/04/2013 19:37:02.924[3308][M]: No Value
28/04/2013 19:37:02.924[3308][M]: Desktop Setting: INTERNETOPENTYPEDIRECT
28/04/2013 19:37:02.924[3308][M]: No Value
28/04/2013 19:37:02.924[3308][M]: INTERNETOPENTYPEDIRECT = 0 [default]
28/04/2013 19:37:02.924[3308][M]: Acquiring lock: 0x6EAB7ADC
28/04/2013 19:37:02.924[3308][M]: Acquired lock: 0x6EAB7ADC
28/04/2013 19:37:02.925[3308][M]: Released lock: 0x6EAB7ADC
28/04/2013 19:37:02.940[3308][M]: sHeader = [Accept-Language:en]
28/04/2013 19:37:03.017[3308][M]: CDownloadBytesImpl::FetchSavesetContent: Reading 44032 bytes
28/04/2013 19:37:03.033[ 372][M]: Waiting for DownloadBytes thread, THID=3308 to exit
28/04/2013 19:37:03.034[3308][M]: CThreadManager::Remove thread THID=3308
28/04/2013 19:37:03.034[3976][M]: Desktop Setting: RESTRICTPOLICYLOOKUP
28/04/2013 19:37:03.034[3976][M]: No Value
28/04/2013 19:37:03.034[3976][M]: Desktop Setting: DisplayItemsUsingOOM
28/04/2013 19:37:03.035[3976][M]: No Value
28/04/2013 19:37:03.035[3976][M]: DisplayItemsUsingOOM = 1 [default]
28/04/2013 19:37:03.037[3976][M]: CShortcutItem::Callback...Display downloaded item
28/04/2013 19:37:03.037[3976][M]: Desktop Setting: RESTRICTPOLICYLOOKUP
28/04/2013 19:37:03.037[3976][M]: No Value
28/04/2013 19:37:03.037[3976][M]: Desktop Setting: DisplayItemsUsingOOM
28/04/2013 19:37:03.037[3976][M]: No Value
28/04/2013 19:37:03.037[3976][M]: DisplayItemsUsingOOM = 1 [default]
28/04/2013 19:37:03.040[3976][M]: CDisplayItem::ReadItemClass: ItemClass [43]
28/04/2013 19:37:03.118[ 372][M]: Deleting CComCallback thread THID=372
28/04/2013 19:37:03.118[ 372][M]: ::CInternetReconnect - refCount : 1
28/04/2013 19:37:03.118[ 372][M]: CComCallback: calling CoUninitialize, thread THID=372
28/04/2013 19:37:03.145[ 372][M]: CComCallback: CoUninitialize completed, thread THID=372
28/04/2013 19:37:03.145[ 372][M]: CThreadManager::Remove thread THID=372
28/04/2013 19:37:05.052[3976][M]: Have unadvised on ItemEvents_10
28/04/2013 19:37:05.052[3976][M]: Have unadvised on InspectorEvents_10
28/04/2013 19:37:05.060[3976][M]: Acquiring lock: 0x6EAB7ADC
28/04/2013 19:37:05.060[3976][M]: Acquired lock: 0x6EAB7ADC
28/04/2013 19:37:05.060[3976][M]: Released lock: 0x6EAB7ADC
28/04/2013 19:37:05.060[3976][M]: Have unadvised on ItemEvents_10

In this part of the trace you can actually see that there are a couple of different threads involved. Interestingly a specific thread is started up in order to do the download, and once it is has finished it cleans itself up. Here it is starting the download:

28/04/2013 19:37:02.918[ 372][M]: Downloading: http://evsql.ev.local/EnterpriseVault/download.asp?VaultID=18A5257C941B9A84F8A6CA597937F3B611110000evsql.ev.local&SaveSetID=201304287177491~201304081913380000~Z~D006154F7F2EA1F13C9DC57A4D6D4C81&FormatType=Unicode&Client=EV10.0.3.1090-Outlook14&Format=MUD&AttachmentID=0

And here it is cleaning itself up:

28/04/2013 19:37:03.118[ 372][M]: Deleting CComCallback thread THID=372
28/04/2013 19:37:03.118[ 372][M]: ::CInternetReconnect – refCount : 1
28/04/2013 19:37:03.118[ 372][M]: CComCallback: calling CoUninitialize, thread THID=372
28/04/2013 19:37:03.145[ 372][M]: CComCallback: CoUninitialize completed, thread THID=372
28/04/2013 19:37:03.145[ 372][M]: CThreadManager::Remove thread THID=372

When full client logging is enabled, then there is of course quite a bit more logged. I’ll not show that here, as it can be a lot of lines of trace.

The retrievals shown so far are straight forward retrievals directly from the Enterprise Vault server. Of course one of the things that many people deploy is Virtual Vault and Vault Cache. So in this next ‘minimum logging level’ trace we see the difference:

28/04/2013 19:51:29.214[4004][M]: Acquiring lock: 0x5F162A20
28/04/2013 19:51:29.215[4004][M]: Acquired lock: 0x5F162A20
28/04/2013 19:51:29.215[4004][M]: Acquiring lock: 0x5F162A20
28/04/2013 19:51:29.215[4004][M]: Acquired lock: 0x5F162A20
28/04/2013 19:51:29.215[4004][M]: Released lock: 0x5F162A20
28/04/2013 19:51:29.215[4004][M]: Released lock: 0x5F162A20
28/04/2013 19:51:29.216[4004][M]: Calling CC to OpenItem
28/04/2013 19:51:29.216[4004][M]: Acquiring lock: 0x02826098
28/04/2013 19:51:29.216[4004][M]: Acquired lock: 0x02826098
28/04/2013 19:51:29.217[4004][M]: CONTENT:STORE: Computing hash using hash algorithm - SHA256
28/04/2013 19:51:29.217[4004][M]: Key: buffeting breather's remorseless skates moat~Vault Admin~2013-04-08T19:13:38~IPM.Note~1
28/04/2013 19:51:29.217[4004][M]: Hash Algorithm: SHA256
28/04/2013 19:51:29.217[4004][M]: Hash Value: 8e3556e965151aad3ba6af242aaf15e4e2fb4f51d058e3d6689bef94421b5607
28/04/2013 19:51:29.218[4004][M]: CONTENT:STORE: Main StoreIdMap will be checked first, then cached StoreIdMap
28/04/2013 19:51:29.218[4004][M]: CONTENT:STORE: Searching using SSID
28/04/2013 19:51:29.218[4004][M]: CONTENT:STORE: Using main StoreIdMap
28/04/2013 19:51:29.218[4004][M]: CONTENT:STORE: Query store map: /ITEMS/ITEM[@SSID='201304287177491~201304081913380000~Z~D006154F7F2EA1F13C9DC57A4D6D4C81']
28/04/2013 19:51:29.218[4004][M]: CONTENT:STORE: Checking for existance of DBID '1'
28/04/2013 19:51:29.219[4004][M]: CONTENT:STORE: Result: ENTRYID = 000000008D130CEF589AC14EBCDACB0BD504A94724002000 DBID = 1
28/04/2013 19:51:29.219[4004][M]: Released lock: 0x02826098
28/04/2013 19:51:29.222[3056][M]: Acquiring lock: 0x5F162A20
28/04/2013 19:51:29.222[3056][M]: Acquired lock: 0x5F162A20
28/04/2013 19:51:29.222[3056][M]: Released lock: 0x5F162A20
28/04/2013 19:51:29.222[3976][M]: Desktop Setting: RESTRICTPOLICYLOOKUP
28/04/2013 19:51:29.222[3976][M]: No Value
28/04/2013 19:51:29.222[3976][M]: Desktop Setting: DisplayItemsUsingOOM
28/04/2013 19:51:29.222[3976][M]: No Value
28/04/2013 19:51:29.223[3976][M]: DisplayItemsUsingOOM = 1 [default]
28/04/2013 19:51:29.224[3976][M]: CDisplayItem::ReadItemClass: ItemClass [43]
28/04/2013 19:51:30.357[3976][M]: Have unadvised on ItemEvents_10
28/04/2013 19:51:30.357[3976][M]: Have unadvised on InspectorEvents_10
28/04/2013 19:51:30.366[3976][M]: Acquiring lock: 0x6EAB7ADC
28/04/2013 19:51:30.366[3976][M]: Acquired lock: 0x6EAB7ADC
28/04/2013 19:51:30.366[3976][M]: Released lock: 0x6EAB7ADC
28/04/2013 19:51:30.367[3976][M]: Have unadvised on ItemEvents_10

As you would expect what happens is that the Outlook Add-in tries to locate the item in Vault Cache first of all. If it is found, then opening the item from Vault Cache saves the round trip to the server in order to fetch the item and display it. That’s exactly what happens here.. The item is in Vault Cache and so it is displayed from there.

The next question is: What happens if Vault Cache is enabled, but, the item I want to view isn’t in Vault Cache? Well a similar process is followed in that the Outlook Add-in will check to see if the item does exist in Vault Cache or not. This time the item doesn’t, so the Outlook Add-in downloads it from the Enterprise Vault server, as it does when there is no Vault Cache configured.

28/04/2013 20:06:54.878[2320][M]: Acquiring lock: 0x024EBA58
28/04/2013 20:06:54.878[2320][M]: Acquired lock: 0x024EBA58
28/04/2013 20:06:54.879[2320][M]: CONTENT:STORE: Computing hash using hash algorithm - SHA256
28/04/2013 20:06:54.879[2320][M]: Key: Continental drift~rob1~2013-04-28T20:06:03~IPM.Note~1
28/04/2013 20:06:54.879[2320][M]: Hash Algorithm: SHA256
28/04/2013 20:06:54.879[2320][M]: Hash Value: 2deb32e1f01f6db997ffe7c0ba9a20be05c9f12a7ce18481914a25264b321c48
28/04/2013 20:06:54.879[2320][M]: CONTENT:STORE: Main StoreIdMap will be checked first, then cached StoreIdMap
28/04/2013 20:06:54.880[2320][M]: CONTENT:STORE: Searching using SSID
28/04/2013 20:06:54.880[2320][M]: CONTENT:STORE: Using main StoreIdMap
28/04/2013 20:06:54.880[2320][M]: CONTENT:STORE: Query store map: /ITEMS/ITEM[@SSID='201304287179590~201304282006030000~Z~D09214689B22127993BED9AED07B47C1']
28/04/2013 20:06:54.881[2320][M]: CONTENT:STORE: Using cached StoreIdMap
28/04/2013 20:06:54.882[2320][M]: CONTENT:STORE: Query store map: /ITEMS/ITEM[@SHA2='2deb32e1f01f6db997ffe7c0ba9a20be05c9f12a7ce18481914a25264b321c48']
28/04/2013 20:06:54.882[2320][M]: CONTENT:STORE: Result: ENTRYID = (null) DBID = 0
28/04/2013 20:06:54.882[2320][M]: Released lock: 0x024EBA58
28/04/2013 20:06:54.882[2320][H]: A COM error occurred: 0x80040205
28/04/2013 20:06:54.883[3552][M]: Acquiring lock: 0x5F362A20
28/04/2013 20:06:54.883[3552][M]: Acquired lock: 0x5F362A20
28/04/2013 20:06:54.883[3552][M]: Released lock: 0x5F362A20
28/04/2013 20:06:54.883[1948][M]: OVReset = 0 [default]
28/04/2013 20:06:54.883[1948][M]: Desktop Setting: OVEnabled
28/04/2013 20:06:54.883[1948][M]: Value: 2
28/04/2013 20:06:54.884[1948][M]: Desktop Setting: RESTRICTPOLICYLOOKUP
28/04/2013 20:06:54.884[1948][M]: No Value
28/04/2013 20:06:54.884[1948][M]: Desktop Setting: RPCOVERHTTPRESTRICTIONS
28/04/2013 20:06:54.884[1948][M]: No Value
28/04/2013 20:06:54.884[1948][M]: RPCOVERHTTPRESTRICTIONS = 255 [default]
28/04/2013 20:06:54.884[1948][M]: Desktop Setting: DefaultWebAppURL
28/04/2013 20:06:54.884[1948][M]: Value: http://evsql.ev.local/EnterpriseVault
28/04/2013 20:06:54.884[1948][M]: HaveConnection::ExecuteTest (6283267) - Starting connection
28/04/2013 20:06:54.885[1948][M]: Desktop Setting: RESTRICTPOLICYLOOKUP
28/04/2013 20:06:54.885[1948][M]: No Value
28/04/2013 20:06:54.885[1948][M]: Desktop Setting: INTERNETOPENTYPEDIRECT
28/04/2013 20:06:54.885[1948][M]: No Value
28/04/2013 20:06:54.885[1948][M]: INTERNETOPENTYPEDIRECT = 0 [default]
28/04/2013 20:06:54.885[1948][M]: HaveConnection::CallBack (6283267) - Callback status is '60'
28/04/2013 20:06:54.886[1948][M]: HaveConnection::CallBack (6283267) - Callback status is '60'
28/04/2013 20:06:54.887[2848][M]: HaveConnection::CallBack (6283267) - Callback status is '30'
28/04/2013 20:06:54.887[2848][M]: HaveConnection::CallBack (6283267) - Callback status is '31'
28/04/2013 20:06:54.887[2848][M]: HaveConnection::CallBack (6283267) - Callback status is '40'
28/04/2013 20:06:54.888[2848][M]: HaveConnection::CallBack (6283267) - Callback status is '41'
28/04/2013 20:06:54.888[2848][M]: HaveConnection::CallBack (6283267) - Callback status is '100'
28/04/2013 20:06:54.889[2848][M]: HaveConnection::CallBack (6283267) - Request has completed
28/04/2013 20:06:54.889[2848][M]: HaveConnection::CallBack (6283267) - Callback status is '70'
28/04/2013 20:06:54.889[2848][M]: HaveConnection::CallBack (6283267) - Request handle closing
28/04/2013 20:06:54.889[1948][M]: HaveConnection::ExecuteTest - Connection test to: evsql.ev.local/EnterpriseVault/clienttest.gif succeeded
28/04/2013 20:06:54.889[1948][M]: HaveConnection::ExecuteTest (6283267) - Ending connection
28/04/2013 20:06:54.889[1948][M]: Successfully contacted the EV web server using: http://evsql.ev.local/EnterpriseVault
28/04/2013 20:06:54.890[1948][M]: ::CInternetReconnect - refCount : 1
28/04/2013 20:06:54.890[1948][M]: CThreadManager::Add thread THID=3196
28/04/2013 20:06:54.900[1948][M]: Acquiring lock: 0x6F0D7ADC
28/04/2013 20:06:54.900[1948][M]: Acquired lock: 0x6F0D7ADC
28/04/2013 20:06:54.900[1948][M]: Released lock: 0x6F0D7ADC
28/04/2013 20:06:54.909[3196][M]: Downloading: http://evsql.ev.local/EnterpriseVault/download.asp?VaultID=18A5257C941B9A84F8A6CA597937F3B611110000evsql.ev.local&SaveSetID=201304287179590~201304282006030000~Z~D09214689B22127993BED9AED07B47C1&FormatType=Unicode&Client=EV10.0.3.1090-Outlook14&Format=MSG&AttachmentID=0
28/04/2013 20:06:54.910[3196][M]: CThreadManager::Add thread THID=716
28/04/2013 20:06:54.910[3196][M]: Desktop Setting: RESTRICTPOLICYLOOKUP
28/04/2013 20:06:54.910[3196][M]: No Value
28/04/2013 20:06:54.910[3196][M]: Desktop Setting: DOWNLOADSHORTCUTHIDEPROGRESS
28/04/2013 20:06:54.911[3196][M]: No Value
28/04/2013 20:06:54.911[3196][M]: DOWNLOADSHORTCUTHIDEPROGRESS = 1 [default]
28/04/2013 20:06:54.911[3196][M]: Download progress dialog delay set to 1 seconds.
28/04/2013 20:06:54.959[ 716][M]: Desktop Setting: RESTRICTPOLICYLOOKUP
28/04/2013 20:06:54.960[ 716][M]: No Value
28/04/2013 20:06:54.960[ 716][M]: Desktop Setting: INTERNETOPENTYPEDIRECT
28/04/2013 20:06:54.960[ 716][M]: No Value
28/04/2013 20:06:54.960[ 716][M]: INTERNETOPENTYPEDIRECT = 0 [default]
28/04/2013 20:06:54.960[ 716][M]: Acquiring lock: 0x6F0D7ADC
28/04/2013 20:06:54.960[ 716][M]: Acquired lock: 0x6F0D7ADC
28/04/2013 20:06:54.960[ 716][M]: Released lock: 0x6F0D7ADC
28/04/2013 20:06:54.975[ 716][M]: sHeader = [Accept-Language:en]
28/04/2013 20:06:55.072[1948][M]: Have unadvised on ItemEvents_10
28/04/2013 20:06:55.147[ 716][M]: CDownloadBytesImpl::FetchSavesetContent: Reading 25088 bytes
28/04/2013 20:06:55.163[3196][M]: Waiting for DownloadBytes thread, THID=716 to exit
28/04/2013 20:06:55.163[ 716][M]: CThreadManager::Remove thread THID=716
28/04/2013 20:06:55.164[1948][M]: Desktop Setting: RESTRICTPOLICYLOOKUP
28/04/2013 20:06:55.164[1948][M]: No Value
28/04/2013 20:06:55.164[1948][M]: Desktop Setting: OVContentDownload
28/04/2013 20:06:55.164[1948][M]: No Value
28/04/2013 20:06:55.164[1948][M]: OVContentDownload = 1 [default]
28/04/2013 20:06:55.165[2388][M]: Acquiring lock: 0x5F362A20
28/04/2013 20:06:55.165[2388][M]: Acquired lock: 0x5F362A20
28/04/2013 20:06:55.165[2388][M]: Acquiring lock: 0x5F362A20
28/04/2013 20:06:55.165[2388][M]: Acquired lock: 0x5F362A20
28/04/2013 20:06:55.165[2388][M]: Released lock: 0x5F362A20
28/04/2013 20:06:55.165[2388][M]: Released lock: 0x5F362A20
28/04/2013 20:06:55.166[2388][M]: Calling CC to InsertBytes
28/04/2013 20:06:55.166[2388][M]: Acquiring lock: 0x024EBA58
28/04/2013 20:06:55.166[2388][M]: Acquired lock: 0x024EBA58
28/04/2013 20:06:55.167[2388][M]: Acquiring lock: 0x024EB6A4
28/04/2013 20:06:55.167[2388][M]: Acquired lock: 0x024EB6A4
28/04/2013 20:06:55.167[2388][M]: Desktop Setting: WORKING_DIRECTORY
28/04/2013 20:06:55.167[2388][M]: Value: C:\Users\rob1\AppData\Local\KVS\Enterprise Vault\4EEB7C7FA3D7C4479F2B03170A822A83\
28/04/2013 20:06:55.167[2388][M]: Released lock: 0x024EB6A4
28/04/2013 20:06:55.167[2388][M]: CONTENT:STORE: Inserting item into store: 1
28/04/2013 20:06:55.168[2388][M]: Token extracted : "C:"
28/04/2013 20:06:55.168[2388][M]: Token extracted : "Users"
28/04/2013 20:06:55.168[2388][M]: Token extracted : "rob1"
28/04/2013 20:06:55.168[2388][M]: Token extracted : "AppData"
28/04/2013 20:06:55.168[2388][M]: Token extracted : "Local"
28/04/2013 20:06:55.168[2388][M]: Token extracted : "KVS"
28/04/2013 20:06:55.168[2388][M]: Token extracted : "Enterprise Vault"
28/04/2013 20:06:55.168[2388][M]: Token extracted : "4EEB7C7FA3D7C4479F2B03170A822A83"
28/04/2013 20:06:55.169[2388][M]: Token extracted : "2013_04_06_0001.db"
28/04/2013 20:06:55.169[2388][M]: Successfully created the registry key HKCU\SOFTWARE\KVS\Enterprise Vault\Client\4EEB7C7FA3D7C4479F2B03170A822A83\WDS Index Data\ReIndex\2013_04_06_0001.db to process the WDS index.
28/04/2013 20:06:55.169[2388][M]: CONTENT:DB: WDSUtil::PersistWDSIndexingInfo returned '1'
28/04/2013 20:06:55.169[2388][M]: CONTENT:DB: GTF - Using Db file 'C:\Users\rob1\AppData\Local\KVS\Enterprise Vault\4EEB7C7FA3D7C4479F2B03170A822A83\2013_04_06_0001.db'
28/04/2013 20:06:55.169[2388][M]: CONTENT:DB: GTF - Date is year '2013-4-28'
28/04/2013 20:06:55.170[2388][M]: CONTENT:DB: GTF - Already got root folder
28/04/2013 20:06:55.170[2388][M]: CONTENT:DB: GTF - Creating folder for year'2013'
28/04/2013 20:06:55.170[2388][M]: CONTENT:DB: GTF - Creating folder for month'04'
28/04/2013 20:06:55.170[2388][M]: CONTENT:DB: GTF - Creating folder for day'28'
28/04/2013 20:06:55.173[2388][M]: Acquiring lock: 0x024EB6A4
28/04/2013 20:06:55.173[2388][M]: Acquired lock: 0x024EB6A4
28/04/2013 20:06:55.173[2388][M]: Released lock: 0x024EB6A4
28/04/2013 20:06:55.173[2388][M]: Desktop Setting: OFFLINE_STORE
28/04/2013 20:06:55.173[2388][M]: Value: 1
28/04/2013 20:06:55.173[2388][M]: Key: Continental drift~rob1~2013-04-28T20:06:03~IPM.Note~1
28/04/2013 20:06:55.174[2388][M]: Hash Algorithm: SHA256
28/04/2013 20:06:55.174[2388][M]: Hash Value: 2deb32e1f01f6db997ffe7c0ba9a20be05c9f12a7ce18481914a25264b321c48
28/04/2013 20:06:55.174[2388][M]: CONTENT:STORE: Items in StoreIdMap is '1111'
28/04/2013 20:06:55.174[2388][M]: Released lock: 0x024EBA58
28/04/2013 20:06:55.176[2388][M]: Acquiring lock: 0x5F362A20
28/04/2013 20:06:55.176[2388][M]: Acquired lock: 0x5F362A20
28/04/2013 20:06:55.176[2388][M]: Released lock: 0x5F362A20
28/04/2013 20:06:55.177[1948][M]: Message has been loaded from the bytes (and now owns them), releasing AutoCOMByteFree
28/04/2013 20:06:55.177[1948][M]: CShortcutItem::Callback...Display downloaded item
28/04/2013 20:06:55.177[1948][M]: Desktop Setting: RESTRICTPOLICYLOOKUP
28/04/2013 20:06:55.177[1948][M]: No Value
28/04/2013 20:06:55.177[1948][M]: Desktop Setting: DisplayItemsUsingOOM
28/04/2013 20:06:55.177[1948][M]: No Value
28/04/2013 20:06:55.177[1948][M]: DisplayItemsUsingOOM = 1 [default]
28/04/2013 20:06:55.179[1948][M]: CDisplayItem::ReadItemClass: ItemClass [43]
28/04/2013 20:06:55.247[3196][M]: Deleting CComCallback thread THID=3196
28/04/2013 20:06:55.247[3196][M]: ::CInternetReconnect - refCount : 1
28/04/2013 20:06:55.247[3196][M]: CComCallback: calling CoUninitialize, thread THID=3196
28/04/2013 20:06:55.271[1948][M]: Have unadvised on ItemEvents_10
28/04/2013 20:06:55.288[3196][M]: CComCallback: CoUninitialize completed, thread THID=3196
28/04/2013 20:06:55.288[3196][M]: CThreadManager::Remove thread THID=3196
28/04/2013 20:06:56.611[1948][M]: Have unadvised on ItemEvents_10
28/04/2013 20:06:56.611[1948][M]: Have unadvised on InspectorEvents_10

Unfortunately the bit you can’t see with this level of tracing is that the item once downloaded, is inserted into Vault Cache. With maximum logging that piece of the puzzle looks like this:

28/04/2013 20:09:40.582[2744][L]: CONTENT:STORE: CCStore::InsertItem: 0x0
28/04/2013 20:09:40.583[2744][L]: CONTENT:STORE: CCStore::GetIndexingItemDate: 0x0
28/04/2013 20:09:40.583[2744][L]: CCGeneral::CalculateIndexingDate: 0x0
28/04/2013 20:09:40.583[2744][L]: CCGeneral::GetMAPIDateProperty: 0x0
28/04/2013 20:09:40.583[2744][L]: ~CCGeneral::GetMAPIDateProperty: 0x40380
28/04/2013 20:09:40.583[2744][L]: ~CCGeneral::CalculateIndexingDate: 0x40380
28/04/2013 20:09:40.583[2744][L]: CONTENT:STORE: ~CCStore::GetIndexingItemDate: 0x40380
28/04/2013 20:09:40.583[2744][L]: CONTENT:STORE: CCStore::MakeSpaceForInsertion: 0x0
28/04/2013 20:09:40.584[2744][L]: CComAutoUnlock<class ATL::CComAutoCriticalSection>::CComAutoUnlock
28/04/2013 20:09:40.584[2744][L]: ~CComAutoUnlock<class ATL::CComAutoCriticalSection>::CComAutoUnlock
28/04/2013 20:09:40.584[2744][L]: CComAutoLock<class ATL::CComAutoCriticalSection>::CComAutoLock
28/04/2013 20:09:40.584[2744][M]: Acquiring lock: 0x027710D4
28/04/2013 20:09:40.584[2744][M]: Acquired lock: 0x027710D4
28/04/2013 20:09:40.584[2744][L]: ~CComAutoLock<class ATL::CComAutoCriticalSection>::CComAutoLock
28/04/2013 20:09:40.584[2744][L]: CONTENT:STORE: CCStoreHelper::SyncPVFileSize
28/04/2013 20:09:40.585[2744][L]: DesktopCommonConfig::GetSetting: 0x0
28/04/2013 20:09:40.585[2744][M]: Desktop Setting: WORKING_DIRECTORY
28/04/2013 20:09:40.585[2744][M]: Value: C:\Users\rob1\AppData\Local\KVS\Enterprise Vault\4EEB7C7FA3D7C4479F2B03170A822A83\
28/04/2013 20:09:40.585[2744][L]: ~DesktopCommonConfig::GetSetting: 0x0
28/04/2013 20:09:40.585[2744][L]: CONTENT:STORE: ~CCStoreHelper::SyncPVFileSize
28/04/2013 20:09:40.585[2744][L]: CComAutoUnlock<class ATL::CComAutoCriticalSection>::~CComAutoUnlock
28/04/2013 20:09:40.586[2744][M]: Released lock: 0x027710D4
28/04/2013 20:09:40.586[2744][L]: ~CComAutoUnlock<class ATL::CComAutoCriticalSection>::~CComAutoUnlock
28/04/2013 20:09:40.586[2744][L]: CONTENT:STORE: ~CCStore::MakeSpaceForInsertion: 0x0
28/04/2013 20:09:40.586[2744][L]: CONTENT:STORE: CCDatabaseList::FindDBByDateAndArchive: 0x0
28/04/2013 20:09:40.586[2744][L]: CONTENT:STORE: CCDatabaseList::Init: 0x0
28/04/2013 20:09:40.586[2744][L]: CComAutoUnlock<class ATL::CComAutoCriticalSection>::CComAutoUnlock
28/04/2013 20:09:40.586[2744][L]: ~CComAutoUnlock<class ATL::CComAutoCriticalSection>::CComAutoUnlock
28/04/2013 20:09:40.587[2744][L]: CComAutoLock<class ATL::CComAutoCriticalSection>::CComAutoLock
28/04/2013 20:09:40.587[2744][M]: Acquiring lock: 0x027BC5A4
28/04/2013 20:09:40.587[2744][M]: Acquired lock: 0x027BC5A4
28/04/2013 20:09:40.587[2744][L]: ~CComAutoLock<class ATL::CComAutoCriticalSection>::CComAutoLock
28/04/2013 20:09:40.587[2744][L]: CONTENT:STORE: CCDatabaseList::Load: 0x0
28/04/2013 20:09:40.587[2744][L]: CONTENT:STORE: CCDatabaseList::GetHighestDbId: 0x0
28/04/2013 20:09:40.598[2744][L]: CONTENT:STORE: ~CCDatabaseList::GetHighestDbId: 0x0
28/04/2013 20:09:40.598[2744][L]: CONTENT:STORE: CCDatabaseList::PopulateValuesForSection
28/04/2013 20:09:40.599[2744][L]: CONTENT:STORE: ~CCDatabaseList::PopulateValuesForSection
28/04/2013 20:09:40.599[2744][L]: CONTENT:STORE: CCDatabaseList::PopulateValuesForSection
28/04/2013 20:09:40.599[2744][L]: CONTENT:STORE: ~CCDatabaseList::PopulateValuesForSection
28/04/2013 20:09:40.599[2744][L]: CONTENT:STORE: CCDatabaseList::PopulateValuesForSection
28/04/2013 20:09:40.599[2744][L]: CONTENT:STORE: ~CCDatabaseList::PopulateValuesForSection
28/04/2013 20:09:40.600[2744][L]: CONTENT:STORE: CCDatabaseList::PopulateValuesForSection
28/04/2013 20:09:40.600[2744][L]: CONTENT:STORE: ~CCDatabaseList::PopulateValuesForSection
28/04/2013 20:09:40.600[2744][L]: CONTENT:STORE: CCDatabaseList::PopulateValuesForSection
28/04/2013 20:09:40.600[2744][L]: CONTENT:STORE: ~CCDatabaseList::PopulateValuesForSection
28/04/2013 20:09:40.600[2744][L]: CONTENT:STORE: ~CCDatabaseList::Load: 0x0
28/04/2013 20:09:40.600[2744][L]: CComAutoUnlock<class ATL::CComAutoCriticalSection>::~CComAutoUnlock
28/04/2013 20:09:40.601[2744][M]: Released lock: 0x027BC5A4
28/04/2013 20:09:40.601[2744][L]: ~CComAutoUnlock<class ATL::CComAutoCriticalSection>::~CComAutoUnlock
28/04/2013 20:09:40.601[2744][L]: CONTENT:STORE: ~CCDatabaseList::Init: 0x0
28/04/2013 20:09:40.601[2744][L]: CONTENT:STORE: ~CCDatabaseList::FindDBByDateAndArchive: 0x0
28/04/2013 20:09:40.601[2744][L]: CONTENT:STORE: CCStore::InitDB: 0x0
28/04/2013 20:09:40.601[2744][L]: DCC::ConfigBase::GetClientStoreKey: 0x0
28/04/2013 20:09:40.601[2744][L]: DesktopCommonConfig::GetClientStoreKey: 0x0
28/04/2013 20:09:40.602[2744][L]: ~DesktopCommonConfig::GetClientStoreKey: 0x0
28/04/2013 20:09:40.602[2744][L]: ~DCC::ConfigBase::GetClientStoreKey: 0x0
28/04/2013 20:09:40.602[2744][L]: DesktopCommonConfig::GetConfigValue: 0x0
28/04/2013 20:09:40.602[2744][L]: DesktopCommonConfig::GetSetting: 0x0
28/04/2013 20:09:40.602[2744][M]: Desktop Setting: RESTRICTPOLICYLOOKUP
28/04/2013 20:09:40.602[2744][M]: No Value
28/04/2013 20:09:40.602[2744][L]: ~DesktopCommonConfig::GetSetting: 0x1
28/04/2013 20:09:40.602[2744][L]: DesktopCommonConfig::GetClientStoreKey: 0x0
28/04/2013 20:09:40.603[2744][L]: ~DesktopCommonConfig::GetClientStoreKey: 0x0
28/04/2013 20:09:40.603[2744][L]: DesktopCommonConfig::GetSetting: 0x0
28/04/2013 20:09:40.603[2744][M]: Desktop Setting: OVAETimeMatchWindow
28/04/2013 20:09:40.603[2744][M]: No Value
28/04/2013 20:09:40.603[2744][L]: ~DesktopCommonConfig::GetSetting: 0x1
28/04/2013 20:09:40.603[2744][M]: OVAETimeMatchWindow = 60 [default]
28/04/2013 20:09:40.603[2744][L]: ~DesktopCommonConfig::GetConfigValue: 0x1
28/04/2013 20:09:40.603[2744][L]: CONTENT:STORE: ~CCStore::InitDB: 0x0
28/04/2013 20:09:40.603[2744][M]: CONTENT:STORE: Inserting item into store: 1
28/04/2013 20:09:40.604[2744][L]: CONTENT:STORE: CCStore::CloseOtherOpenDb
28/04/2013 20:09:40.604[2744][L]: CONTENT:STORE: ~CCStore::CloseOtherOpenDb
28/04/2013 20:09:40.604[2744][L]: CONTENT:DB: CCDatabase::InsertItem: 0x0

Hopefully that has given you a little insight in to the work that goes on behind the scenes when you retrieve an item using the Enterprise Vault Outlook Add-in. It’s not quite as simple as you think!

If you enjoyed this post, please consider leaving a comment or subscribing to the RSS feed to have future articles delivered to your feed reader.

 Leave a Reply

You may use these HTML tags and attributes: <a href="" title=""> <abbr title=""> <acronym title=""> <b> <blockquote cite=""> <cite> <code> <del datetime=""> <em> <i> <q cite=""> <s> <strike> <strong>

(required)

(required)