Video Screencast Help
Protect Your POS Environment Against Retail Data Breaches. Learn More.
Archiving and eDiscovery Community Blog

Retrieving an Item using the Enterprise Vault Outlook Add-in

Created: 26 May 2013 • Updated: 29 May 2014
Rob.Wilcox's picture
0 0 Votes
Login to vote

 

Retrieving 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...

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...

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...

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!