http://bugs.winehq.org/show_bug.cgi?id=34989
Anastasius Focht focht@gmx.net changed:
What |Removed |Added ---------------------------------------------------------------------------- Status|UNCONFIRMED |NEW CC| |focht@gmx.net Component|-unknown |msi Summary|SourceTree can't install |Atlassian SourceTree | |(Mercurial and Git client) | |v1.3.2 installer hangs | |(deferred type 1 custom | |action executed before | |regular type 1 custom | |action) Ever Confirmed|0 |1
--- Comment #2 from Anastasius Focht focht@gmx.net 2013-11-24 15:23:08 CST --- Hello folks,
confirming.
--- quote --- In terminal output, I found -- fixme:shell:SHGetKnownFolderPath flags 0x00004400 not supported -- So I guess this is a shell32 bug --- quote ---
FIXME's are not necessarily bugs.
The installer creates a child process and some bidirectional (message mode) pipes which both processes use to communicate with each other.
At the point of the "hang" the client is blocking on a pipe read in some msi custom action.
--- snip --- Wine-dbg>info process pid threads executable (all id:s are in hex)
00000023 4 'SourceTreeSetup_1.3.2.exe'
00000032 2 _ 'SourceTreeSetup_1.3.2.exe' 00000021 1 'explorer.exe' 0000000e 5 'services.exe' 0000001a 3 _ 'plugplay.exe' 00000012 4 _ 'winedevice.exe'
Wine-dbg>info thread process tid prio (all id:s are in hex) ... 00000023 (D) Z:\home\focht\Downloads\SourceTreeSetup_1.3.2.exe 0000002b 0 0000002a 0 00000025 0 00000024 0 00000032 (D) Z:\home\focht\Downloads\SourceTreeSetup_1.3.2.exe 00000039 0 00000033 0 <== --- snip ---
Server/parent creating two pipes:
--- snip --- 002a:Call KERNEL32.CreateNamedPipeW(0014db28 L"\\.\pipe\ToServerAdvinst_Estimate_Z:\home\focht\Downloads\SourceTreeSetup_1.3.2.exe",00000003,00000006,000000ff,00007f90,00007f90,00001388,00000000) ret=00480d7c 002a:Ret KERNEL32.CreateNamedPipeW() retval=0000009c ret=00480d7c ... 002a:Call KERNEL32.CreateNamedPipeW(0014f020 L"\\.\pipe\ToServerAdvinst_Extract_Z:\home\focht\Downloads\SourceTreeSetup_1.3.2.exe",00000003,00000006,000000ff,00007f90,00007f90,00001388,00000000) ret=00480d7c 002a:Ret KERNEL32.CreateNamedPipeW() retval=000000a0 ret=00480d7c ... --- snip ---
Server thread tid 0x2a waiting for client connect to "\\.\pipe\ToServerAdvinst_Estimate_Z:\home\focht\Downloads\SourceTreeSetup_1.3.2.exe":
--- snip --- 002a:Call KERNEL32.ConnectNamedPipe(0000009c,00000000) ret=00480f8a --- snip ---
Another pipe (served from tid 0x2b) for child process which is created a short time later:
--- snip --- 002b:Call KERNEL32.CreateNamedPipeW(005bf580 L"\\.\pipe\ToServer35",00000003,00000006,000000ff,00000400,00000400,00001388,00000000) ret=00498839 002b:Ret KERNEL32.CreateNamedPipeW() retval=000000f8 ret=00498839 ... 002b:Call KERNEL32.CreateProcessW(005bf5f8 L"Z:\home\focht\Downloads\SourceTreeSetup_1.3.2.exe",005c0cd0 L"Z:\home\focht\Downloads\SourceTreeSetup_1.3.2.exe /i "C:\users\Public\Application Data\Atlassian\SourceTree 1.3.2\install\SourceTreeSetup_1.3.2.msi" EXECUTEACTION="INSTALL" SECONDSEQUENCE="1" CLIENTPROCESSID="35" ADDLOCAL="MainFeature" ACTION="INSTALL" CLIENTUILEVEL="0" ALLUS"...,00000000,00000000,00000000,00000000,00000000,00000000,00bade0c,00bae104) ret=004a086a ... 0032:Call KERNEL32.__wine_kernel_init() ret=7bc599cc 002b:Ret KERNEL32.CreateProcessW() retval=00000001 ret=004a086a ... 002b:Call KERNEL32.ConnectNamedPipe(000000f8,00000000) ret=00498a35 ... --- snip ---
(working) sequence of client<->server pipe "\\.\pipe\ToServer35" communication:
--- snip --- 0032:Call KERNEL32.CreateFileW(0058e768 L"\\.\pipe\ToServer35",c0000000,00000000,00000000,00000003,00000000,00000000) ret=0049885f 0032:Ret KERNEL32.CreateFileW() retval=000000b0 ret=0049885f ... 0032:Call KERNEL32.WriteFile(000000b0,0058e768,00000010,0033e108,00000000) ret=00498b95 002b:Ret KERNEL32.ConnectNamedPipe() retval=00000001 ret=00498a35 0032:Ret KERNEL32.WriteFile() retval=00000001 ret=00498b95 002b:Call KERNEL32.ReadFile(000000f8,005bf8d8,00000400,00badcc4,00000000) ret=00498aaf 0032:Call KERNEL32.ReadFile(000000b0,0058aa58,00000400,0033e074,00000000) ret=00498aaf 002b:Ret KERNEL32.ReadFile() retval=00000001 ret=00498aaf ... 002b:Call KERNEL32.PeekNamedPipe(000000f8,00000000,00000000,00000000,00000000,00badcc8) ret=00498b09 002b:Ret KERNEL32.PeekNamedPipe() retval=00000001 ret=00498b09 ... 002b:Call KERNEL32.WriteFile(000000f8,00badd3c,0000000a,00badd20,00000000) ret=00498bea 002b:Ret KERNEL32.WriteFile() retval=00000001 ret=00498bea 0032:Ret KERNEL32.ReadFile() retval=00000001 ret=00498aaf 002b:Call KERNEL32.FlushFileBuffers(000000f8) ret=00498bf3 0032:Call KERNEL32.PeekNamedPipe(000000b0,00000000,00000000,00000000,00000000,0033e078) ret=00498b09 0032:Ret KERNEL32.PeekNamedPipe() retval=00000001 ret=00498b09 0032:Call ntdll.RtlFreeHeap(00584000,00000000,0058e768) ret=004b0df8 0032:Ret ntdll.RtlFreeHeap() retval=00000001 ret=004b0df8 002b:Ret KERNEL32.FlushFileBuffers() retval=00000001 ret=00498bf3 ... 002b:Call KERNEL32.ConnectNamedPipe(000000f8,00000000) ret=00498a35 0032:Call KERNEL32.WriteFile(000000b0,0058fb10,0000004a,0033e108,00000000) ret=00498b95 0032:Ret KERNEL32.WriteFile() retval=00000001 ret=00498b95 0032:Call KERNEL32.ReadFile(000000b0,0058aa58,00000400,0033e074,00000000) ret=00498aaf 002b:Ret KERNEL32.ConnectNamedPipe() retval=00000000 ret=00498a35 --- snip ---
Messages containing unicode ascii strings are exchanged over pipe. Looks like some proprietary installer protocol.
At some point a custom action "AI_ExtractFiles" (ExtractSourceFiles) is executed on the client side:
--- snip --- ... 0032:trace:msi:ACTION_CustomAction Handling custom action L"AI_ExtractFiles" (401 L"Prereq.dll" L"ExtractSourceFiles") ... 0032:trace:msi:HANDLE_CustomType1 Calling function L"ExtractSourceFiles" from L"C:\users\focht\Temp\msicd98.tmp" ... 0032:Call ole32.CoCreateGuid(008fd7b4) ret=7d531a09 0032:Call rpcrt4.UuidCreate(008fd7b4) ret=7e69c445 0032:Call advapi32.SystemFunction036(008fd7b4,00000010) ret=7e639113 0032:Ret advapi32.SystemFunction036() retval=00000001 ret=7e639113 0032:Ret rpcrt4.UuidCreate() retval=00000000 ret=7e69c445 0032:Ret ole32.CoCreateGuid() retval=00000000 ret=7d531a09 0032:Call KERNEL32.CreateThread(00000000,00000000,7d531866,008fd7b4,00000000,00000000) ret=7d531a7b 0032:Ret KERNEL32.CreateThread() retval=000000d8 ret=7d531a7b 0032:trace:msi:wait_thread_handle waiting for L"AI_ExtractFiles" ... 0038:Starting thread proc 0x7d531866 (arg=0x8fd7b4) ... 0038:Call KERNEL32.LoadLibraryW(0015e964 L"C:\users\focht\Temp\msicd98.tmp") ret=7d5314d7 0038:Ret KERNEL32.LoadLibraryW() retval=00340000 ret=7d5314d7 ... 0038:Call KERNEL32.GetProcAddress(00340000,00919c48 "ExtractSourceFiles") ret=7d531577 0038:Ret KERNEL32.GetProcAddress() retval=0035980b ret=7d531577 ... 0038:trace:msi:alloc_msi_remote_handle 0x9067f8 -> 4 0038:trace:msi:ACTION_CallDllFunction calling L"ExtractSourceFiles" ... 0038:Call KERNEL32.CreateFileA(0091ad78 "\\.\pipe\ToServerAdvinst_Extract_Z:\home\focht\Downloads\SourceTreeSetup_1.3.2.exe",c0000000,00000000,00000000,00000003,00000000,00000000) ret=00348e1f 0038:Ret KERNEL32.CreateFileA() retval=000000dc ret=00348e1f ... 0038:Call KERNEL32.WriteFile(000000dc,0091afb8,00000004,093ce7c4,00000000) ret=003490ca 0038:Ret KERNEL32.WriteFile() retval=00000001 ret=003490ca 0038:Call KERNEL32.FlushFileBuffers(000000dc) ret=003490d3 0038:Ret KERNEL32.FlushFileBuffers() retval=00000001 ret=003490d3 0038:Call ntdll.RtlFreeHeap(00110000,00000000,0091afa8) ret=00362277 0038:Ret ntdll.RtlFreeHeap() retval=00000001 ret=00362277 0038:Call KERNEL32.ConnectNamedPipe(000000dc,00000000) ret=00349011 0038:fixme:ntdll:server_ioctl_file Unsupported ioctl 110008 (device=11 access=0 func=2 method=0) 0038:Ret KERNEL32.ConnectNamedPipe() retval=00000000 ret=00349011 0038:Call KERNEL32.GetLastError() ret=0034901b 0038:Ret KERNEL32.GetLastError() retval=00000032 ret=0034901b 0038:Call KERNEL32.ReadFile(000000dc,091c30b0,00007f90,093ce7c0,00000000) ret=0034904e 0025:Ret KERNEL32.WaitForSingleObject() retval=00000102 ret=00472b8c 0025:Call KERNEL32.WaitForSingleObject(00000060,000000c8) ret=00472b8c 0025:Ret KERNEL32.WaitForSingleObject() retval=00000102 ret=00472b8c 0025:Call KERNEL32.WaitForSingleObject(00000060,000000c8) ret=00472b8c ... --- snip ---
At this point the client (tid 0x38) hangs.
The strange ConnectNamedPipe() call which looks like server-side pipe code can be safely ignored. It's a no-op on pipe client and for whatever reason executed here (app bug?).
The hang results from the second pipe being opened and written to/read from "\\.\pipe\ToServerAdvinst_Extract_Z:\home\focht\Downloads\SourceTreeSetup_1.3.2.exe" for which the pipe server has no pending ConnectNamedPipe() call.
Looking at the exports list of that custom action dll:
--- snip --- ... EstimateExtractFiles ExtractSourceFiles ... --- snip ---
It seems "EstimateExtractFiles" which connects to first pipe must be called prior "ExtractSourceFiles".
Searching the trace log with "custom action" yields:
--- snip --- ... 002b:trace:msi:ACTION_CustomAction Handling custom action L"AI_SET_INSTALL" (33 L"AI_INSTALL" L"1") 002b:trace:msi:ACTION_CustomAction Handling custom action L"AI_ResolveLocalizedCredentials" (1 L"aicustact.dll" L"GetLocalizedCredentials") 002c:trace:msi:DllThread custom action (2c) started 002c:trace:msi:DllThread custom action (2c) returned 0 002b:trace:msi:ACTION_CustomAction Handling custom action L"AI_ResolveKnownFolders" (1 L"aicustact.dll" L"AI_ResolveKnownFolders") 002d:trace:msi:DllThread custom action (2d) started 002d:trace:msi:DllThread custom action (2d) returned 0 002b:trace:msi:ACTION_CustomAction Handling custom action L"AI_BACKUP_AI_SETUPEXEPATH" (33 L"AI_SETUPEXEPATH_ORIGINAL" L"[AI_SETUPEXEPATH]") 002b:trace:msi:ACTION_CustomAction Handling custom action L"AI_RESTORE_AI_SETUPEXEPATH" (33 L"AI_SETUPEXEPATH" L"[AI_SETUPEXEPATH_ORIGINAL]") 002b:trace:msi:ACTION_CustomAction Handling custom action L"AI_AppSearchEx" (1 L"Prereq.dll" L"DoAppSearchEx") 002e:trace:msi:DllThread custom action (2e) started 002e:warn:msi:MsiGetDatabaseState MsiGetDatabaseState not allowed during a custom action! 002e:warn:msi:MsiGetDatabaseState MsiGetDatabaseState not allowed during a custom action! 002e:warn:msi:MsiGetDatabaseState MsiGetDatabaseState not allowed during a custom action! 002e:trace:msi:DllThread custom action (2e) returned 0 002b:trace:msi:ACTION_CustomAction Handling custom action L"AI_SETMIXINSTLOCATION" (1 L"aicustact.dll" L"MixedAllUsersInstallLocation") 002f:trace:msi:DllThread custom action (2f) started 002f:trace:msi:DllThread custom action (2f) returned 0 002b:trace:msi:ACTION_CustomAction Handling custom action L"AI_RESTORE_LOCATION" (41 L"aicustact.dll" L"RestoreLocation") 0030:trace:msi:DllThread custom action (30) started 0030:trace:msi:DllThread custom action (30) returned 0 002b:trace:msi:ACTION_CustomAction Handling custom action L"SET_APPDIR" (133 L"APPDIR" L"[AI_UserProgramFiles][Manufacturer]\[ProductName]") 002b:trace:msi:ACTION_CustomAction Handling custom action L"SET_SHORTCUTDIR" (133 L"SHORTCUTDIR" L"[ProgramMenuFolder][Manufacturer]\[ProductName]") ... 0032:trace:msi:ACTION_CustomAction Handling custom action L"AI_GetArpIconPath" (1 L"aicustact.dll" L"GetArpIconPath") 0033:trace:msi:DllThread custom action (33) started 0033:trace:msi:DllThread custom action (33) returned 0 0032:trace:msi:ACTION_CustomAction Handling custom action L"AI_ResolveLocalizedCredentials" (1 L"aicustact.dll" L"GetLocalizedCredentials") 0034:trace:msi:DllThread custom action (34) started 0034:trace:msi:DllThread custom action (34) returned 0 0032:trace:msi:ACTION_CustomAction Handling custom action L"AI_ResolveKnownFolders" (1 L"aicustact.dll" L"AI_ResolveKnownFolders") 0035:trace:msi:DllThread custom action (35) started 0035:trace:msi:DllThread custom action (35) returned 0 0032:trace:msi:ACTION_CustomAction Handling custom action L"AI_BACKUP_AI_SETUPEXEPATH" (33 L"AI_SETUPEXEPATH_ORIGINAL" L"[AI_SETUPEXEPATH]") 0032:trace:msi:ACTION_CustomAction Handling custom action L"AI_RESTORE_AI_SETUPEXEPATH" (33 L"AI_SETUPEXEPATH" L"[AI_SETUPEXEPATH_ORIGINAL]") 0032:trace:msi:ACTION_CustomAction Handling custom action L"AI_AppSearchEx" (1 L"Prereq.dll" L"DoAppSearchEx") 0036:trace:msi:DllThread custom action (36) started 0036:warn:msi:MsiGetDatabaseState MsiGetDatabaseState not allowed during a custom action! 0036:warn:msi:MsiGetDatabaseState MsiGetDatabaseState not allowed during a custom action! 0036:warn:msi:MsiGetDatabaseState MsiGetDatabaseState not allowed during a custom action! 0036:trace:msi:DllThread custom action (36) returned 0 0032:trace:msi:ACTION_CustomAction Handling custom action L"AI_SETMIXINSTLOCATION" (1 L"aicustact.dll" L"MixedAllUsersInstallLocation") 0037:trace:msi:DllThread custom action (37) started 0037:trace:msi:DllThread custom action (37) returned 0 0032:trace:msi:ACTION_CustomAction Handling custom action L"SET_TARGETDIR_TO_APPDIR" (33 L"TARGETDIR" L"[APPDIR]") 0032:trace:msi:ACTION_CustomAction Handling custom action L"AI_STORE_LOCATION" (33 L"ARPINSTALLLOCATION" L"[APPDIR]") 0032:trace:msi:ACTION_CustomAction Handling custom action L"AI_DATA_SETTER" (33 L"AI_ExtractFiles" L"[AI_SETUPEXEPATH]") 0032:trace:msi:ACTION_CustomAction Handling custom action L"AI_ExtractFiles" (401 L"Prereq.dll" L"ExtractSourceFiles") 0038:trace:msi:DllThread custom action (38) started --- snip ---
Dumping the "custom action" table from extracted "SourceTreeSetup_1.3.2.msi" with ORCA:
--- snip --- Action Type Source Target ExtendedType s72 i2 S72 S0 I4 ... AI_ExtractFiles 1025 Prereq.dll ExtractSourceFiles ... AI_EstimateExtractFiles 1 Prereq.dll EstimateExtractFiles --- snip ---
Dumping "InstallExecuteSequence" table:
--- snip --- Action Condition Sequence s72 S255 I2 ... AI_ExtractFiles 3998 ... AI_EstimateExtractFiles 3999 --- snip ---
"AI_EstimateExtractFiles" has a higher sequence id than "AI_ExtractFiles".
The important thing here is the type of custom action (see "custom action" table):
"AI_EstimateExtractFiles" -> type 1 custom action
"AI_ExtractFiles" -> type 1025 = type 1 custom action that is deferred (+1024).
Wine's msi executes "AI_ExtractFiles" as standard type 1 custom action in order of sequence id.
Regards