16.10.2020 19:18, Tom Lane wrote:
> Oh, very interesting.
> Now that you have it somewhat in captivity, maybe you could determine
> some things:
>
> 1. Is it only stdout that's affected? What of other stdio streams?
> (Note that testing stderr might be tricky because it's probably
> line-buffered.)
stderr is affected too. Just replacing stdout with stderr in connect.c
and 000_connect.pl gives the same result.
Moreover, the following modification:
...
outfile = fopen("out", "w");
...
fprintf(stdout, "stdout test\n");
fprintf(stderr, "stderr test\n");
fprintf(outfile, "outfile test\n");
WSACleanup();
...
---
for (my $i =0; $i < 100000; $i++) {
unlink('out');
IPC::Run::run(\@cmd, '>', \$stdout, '2>', \$stderr);
open(my $fh, '<', 'out') or die $!;
my $fileout = <$fh>;
ok(defined $fileout && $fileout ne '');
close($fh);
}
detects similar failures too. (On a fail the out file exists but has
zero size.)
> 2. Does an fflush() just before, or just after, WSACleanup() fix it?
"fflush(NULL);" just before or after WSACleanup() fixes things.
I've managed to record in ProcMon the activity log for a failed run
(aside normal runs). Excerpts from the log are attached. As we can see,
the failed process doesn't even try to write into IPC-Run's temp file.
> Depending on your answers to the above, maybe some hack like this
> would be acceptable:
>
> free(conn);
>
> #ifdef WIN32
> + fflush(NULL);
> WSACleanup();
> #endif
> }
>
> It's not very nice for a library to be doing global things like that,
> but if the alternative is loss of output, maybe we should.
But now we see that the WSACleanup call is a global thing by itself.
> But wait a minute: I just looked at Microsoft's docs [1] and found
>
> In a multithreaded environment, WSACleanup terminates Windows Sockets
> operations for all threads.
>
> This makes me (a) wonder if that explains the side-effects on stdio,
> and (b) question why libpq is calling WSACleanup at all.
> What if we arranged to call WSAStartup just once, during the first
> libpq connection-open in a process, and then never did WSACleanup?
> Surely the OS can cope with that, and it eliminates any risk that
> WSACleanup breaks something.
What bothers me is:
There must be a call to *WSACleanup* for each successful call to
WSAStartup
<https://docs.microsoft.com/en-us/windows/desktop/api/winsock/nf-winsock-wsastartup>.
Only the final *WSACleanup* function call performs the actual
cleanup. The preceding calls simply decrement an internal reference
count in the WS2_32.DLL.
So third-party application developers should understand that when using
libpq they would have to call WSACleanup one more time to perform "the
actual cleanup". (And thus WSAStartup is kind of like a global thing too.)
But may be it's a way better than to have a confirmed risk of losing data.
Best regards,
Alexander
"Time of Day","Process Name","PID","Operation","Path","Result","Detail"
"6:46:00.6867994 AM","connect.EXE","1964","RegQueryKey","HKLM","SUCCESS","Query: <Unknown: 7 >"
"6:46:00.6868045 AM","connect.EXE","1964","RegOpenKey","HKLM\System\CurrentControlSet\Services\Tcpip\Parameters\Winsock","REPARSE","Desired Access: Read"
"6:46:00.6868108 AM","connect.EXE","1964","RegOpenKey","HKLM\System\CurrentControlSet\Services\Tcpip\Parameters\Winsock","SUCCESS","Desired Access: Read"
"6:46:00.6868173 AM","connect.EXE","1964","RegQueryValue","HKLM\System\CurrentControlSet\Services\Tcpip\Parameters\Winsock\MinSockaddrLength","SUCCESS","Type: REG_DWORD, Length: 4, Data: 16"
"6:46:00.6868222 AM","connect.EXE","1964","RegQueryValue","HKLM\System\CurrentControlSet\Services\Tcpip\Parameters\Winsock\MaxSockaddrLength","SUCCESS","Type: REG_DWORD, Length: 4, Data: 16"
"6:46:00.6868270 AM","connect.EXE","1964","RegQueryValue","HKLM\System\CurrentControlSet\Services\Tcpip\Parameters\Winsock\UseDelayedAcceptance","SUCCESS","Type: REG_DWORD, Length: 4, Data: 0"
"6:46:00.6868324 AM","connect.EXE","1964","RegCloseKey","HKLM\System\CurrentControlSet\Services\Tcpip\Parameters\Winsock","SUCCESS",""
"6:46:00.6871675 AM","connect.EXE","1964","RegCloseKey","HKLM\System\CurrentControlSet\Services\WinSock2\Parameters\Protocol_Catalog9","SUCCESS",""
"6:46:00.6872047 AM","connect.EXE","1964","RegCloseKey","HKLM\System\CurrentControlSet\Services\WinSock2\Parameters\NameSpace_Catalog5","SUCCESS",""
"6:46:00.6873043 AM","connect.EXE","1964","FASTIO_NETWORK_QUERY_OPEN","C:\Windows\System32\kernel.appcore.dll","FAST IO DISALLOWED",""
"6:46:00.6874633 AM","connect.EXE","1964","IRP_MJ_CREATE","C:\Windows\System32\kernel.appcore.dll","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"6:46:00.6874866 AM","connect.EXE","1964","FASTIO_QUERY_INFORMATION","C:\Windows\System32\kernel.appcore.dll","SUCCESS","Type: QueryBasicInformationFile, CreationTime: 11/21/2014 7:47:53 AM, LastAccessTime: 11/21/2014 7:47:53 AM, LastWriteTime: 11/21/2014 7:47:53 AM, ChangeTime: 12/4/2019 2:31:34 PM, FileAttributes: A"
"6:46:00.6874966 AM","connect.EXE","1964","IRP_MJ_CLEANUP","C:\Windows\System32\kernel.appcore.dll","SUCCESS",""
"6:46:00.6875074 AM","connect.EXE","1964","IRP_MJ_CLOSE","C:\Windows\System32\kernel.appcore.dll","SUCCESS",""
"6:46:00.6875782 AM","connect.EXE","1964","IRP_MJ_CREATE","C:\Windows\System32\kernel.appcore.dll","SUCCESS","Desired Access: Read Data/List Directory, Execute/Traverse, Synchronize, Disposition: Open, Options: Synchronous IO Non-Alert, Non-Directory File, Attributes: n/a, ShareMode: Read, Delete, AllocationSize: n/a, OpenResult: Opened"
"6:46:00.6875970 AM","connect.EXE","1964","FASTIO_ACQUIRE_FOR_SECTION_SYNCHRONIZATION","C:\Windows\System32\kernel.appcore.dll","FILE LOCKED WITH ONLY READERS","SyncType: SyncTypeCreateSection, PageProtection: "
"6:46:00.6876058 AM","connect.EXE","1964","FASTIO_RELEASE_FOR_SECTION_SYNCHRONIZATION","C:\Windows\System32\kernel.appcore.dll","SUCCESS",""
"6:46:00.6876143 AM","connect.EXE","1964","FASTIO_ACQUIRE_FOR_SECTION_SYNCHRONIZATION","C:\Windows\System32\kernel.appcore.dll","SUCCESS","SyncType: SyncTypeOther"
"6:46:00.6876789 AM","connect.EXE","1964","FASTIO_RELEASE_FOR_SECTION_SYNCHRONIZATION","C:\Windows\System32\kernel.appcore.dll","SUCCESS",""
"6:46:00.6878993 AM","connect.EXE","1964","IRP_MJ_CLEANUP","C:\Windows\System32\kernel.appcore.dll","SUCCESS",""
"6:46:00.6879153 AM","connect.EXE","1964","IRP_MJ_CLOSE","C:\Windows\System32\kernel.appcore.dll","SUCCESS",""
"6:46:00.6884862 AM","connect.EXE","1964","RegOpenKey","HKLM\SYSTEM\CurrentControlSet\Control\Session Manager","REPARSE","Desired Access: Query Value, Enumerate Sub Keys"
"6:46:00.6885024 AM","connect.EXE","1964","RegOpenKey","HKLM\System\CurrentControlSet\Control\Session Manager","SUCCESS","Desired Access: Query Value, Enumerate Sub Keys"
"6:46:00.6885109 AM","connect.EXE","1964","RegQueryValue","HKLM\System\CurrentControlSet\Control\SESSION MANAGER\ResourcePolicies","NAME NOT FOUND","Length: 24"
"6:46:00.6885183 AM","connect.EXE","1964","RegCloseKey","HKLM\System\CurrentControlSet\Control\SESSION MANAGER","SUCCESS",""
"6:46:00.6885954 AM","connect.EXE","1964","IRP_MJ_WRITE","C:\Users\Administrator\AppData\Local\Temp\IPC-Run.tmp\Win32io-002756-00053864","SUCCESS","Offset: 0, Length: 13, Priority: Normal"
"6:46:00.6886284 AM","connect.EXE","1964","IRP_MJ_WRITE","C:\$LogFile","SUCCESS","Offset: 114,688, Length: 4,096, I/O Flags: Non-cached, Paging I/O, Synchronous Paging I/O, Priority: Normal"
"6:46:00.6888096 AM","connect.EXE","1964","IRP_MJ_WRITE","C:\$LogFile","SUCCESS","Offset: 49,152, Length: 4,096, I/O Flags: Non-cached, Paging I/O, Synchronous Paging I/O, Priority: Normal"
"6:46:00.6889418 AM","connect.EXE","1964","FASTIO_ACQUIRE_FOR_CC_FLUSH","C:\Users\Administrator\AppData\Local\Temp\IPC-Run.tmp\Win32io-002756-00053864","SUCCESS",""
"6:46:00.6889563 AM","connect.EXE","1964","IRP_MJ_WRITE","C:\Users\Administrator\AppData\Local\Temp\IPC-Run.tmp\Win32io-002756-00053864","SUCCESS","Offset: 0, Length: 4,096, I/O Flags: Non-cached, Paging I/O, Synchronous Paging I/O, Priority: Normal"
"6:46:00.6950728 AM","connect.EXE","1964","FASTIO_ACQUIRE_FOR_CC_FLUSH","C:\$Mft","SUCCESS",""
"6:46:00.6950952 AM","connect.EXE","1964","IRP_MJ_WRITE","C:\$Mft","SUCCESS","Offset: 217,112,576, Length: 4,096, I/O Flags: Non-cached, Paging I/O, Synchronous Paging I/O, Priority: Normal"
"6:46:00.6952326 AM","connect.EXE","1964","FASTIO_RELEASE_FOR_CC_FLUSH","C:\$Mft","SUCCESS",""
"6:46:00.6952494 AM","connect.EXE","1964","FASTIO_RELEASE_FOR_CC_FLUSH","C:\Users\Administrator\AppData\Local\Temp\IPC-Run.tmp\Win32io-002756-00053864","SUCCESS",""
"6:46:00.6952847 AM","connect.EXE","1964","IRP_MJ_WRITE","C:\Users\Administrator\AppData\Local\Temp\IPC-Run.tmp\Win32io-002756-00053865","SUCCESS","Offset: 0, Length: 13, Priority: Normal"
"6:46:00.6953435 AM","connect.EXE","1964","IRP_MJ_WRITE","C:\$LogFile","SUCCESS","Offset: 114,688, Length: 4,096, I/O Flags: Non-cached, Paging I/O, Synchronous Paging I/O, Priority: Normal"
"6:46:00.6955444 AM","connect.EXE","1964","IRP_MJ_WRITE","C:\$LogFile","SUCCESS","Offset: 53,248, Length: 4,096, I/O Flags: Non-cached, Paging I/O, Synchronous Paging I/O, Priority: Normal"
"6:46:00.6957051 AM","connect.EXE","1964","FASTIO_ACQUIRE_FOR_CC_FLUSH","C:\Users\Administrator\AppData\Local\Temp\IPC-Run.tmp\Win32io-002756-00053865","SUCCESS",""
"6:46:00.6957250 AM","connect.EXE","1964","IRP_MJ_WRITE","C:\Users\Administrator\AppData\Local\Temp\IPC-Run.tmp\Win32io-002756-00053865","SUCCESS","Offset: 0, Length: 4,096, I/O Flags: Non-cached, Paging I/O, Synchronous Paging I/O, Priority: Normal"
"6:46:00.7065464 AM","connect.EXE","1964","FASTIO_ACQUIRE_FOR_CC_FLUSH","C:\$Mft","SUCCESS",""
"6:46:00.7065652 AM","connect.EXE","1964","IRP_MJ_WRITE","C:\$Mft","SUCCESS","Offset: 220,413,952, Length: 4,096, I/O Flags: Non-cached, Paging I/O, Synchronous Paging I/O, Priority: Normal"
"6:46:00.7067828 AM","connect.EXE","1964","FASTIO_RELEASE_FOR_CC_FLUSH","C:\$Mft","SUCCESS",""
"6:46:00.7067993 AM","connect.EXE","1964","FASTIO_RELEASE_FOR_CC_FLUSH","C:\Users\Administrator\AppData\Local\Temp\IPC-Run.tmp\Win32io-002756-00053865","SUCCESS",""
"6:46:00.7070538 AM","connect.EXE","1964","IRP_MJ_CLEANUP","C:\src\postgresql\src\test\modules\connect","SUCCESS",""
"6:46:00.7070627 AM","connect.EXE","1964","IRP_MJ_CLOSE","C:\src\postgresql\src\test\modules\connect","SUCCESS",""
"6:46:00.7070846 AM","connect.EXE","1964","RegCloseKey","HKLM\System\CurrentControlSet\Control\SESSION MANAGER","SUCCESS",""
"6:46:00.7071136 AM","connect.EXE","1964","RegCloseKey","HKLM\System\CurrentControlSet\Control\Nls\Sorting\Versions","SUCCESS",""
"6:46:00.7071181 AM","connect.EXE","1964","RegCloseKey","HKLM","SUCCESS",""
"6:46:00.7195845 AM","perl.exe","2756","FASTIO_READ","C:\Users\Administrator\AppData\Local\Temp\IPC-Run.tmp\Win32io-002756-00053864","SUCCESS","Offset: 0, Length: 13"
"6:46:00.7196977 AM","perl.exe","2756","FASTIO_READ","C:\Users\Administrator\AppData\Local\Temp\IPC-Run.tmp\Win32io-002756-00053864","END OF FILE","Offset: 13, Length: 999,999"
"6:46:00.7197375 AM","perl.exe","2756","IRP_MJ_DEVICE_CONTROL","C:\Users\Administrator\AppData\Local\Temp\IPC-Run.tmp\Win32io-002756-00053864","FAST IO DISALLOWED","Control: 0x12043 (Device:0x1 Function:2064 Method: 3)"
"Time of Day","Process Name","PID","Operation","Path","Result","Detail"
"6:46:01.7192801 AM","connect.EXE","912","RegQueryKey","HKLM","SUCCESS","Query: <Unknown: 7 >"
"6:46:01.7192850 AM","connect.EXE","912","RegOpenKey","HKLM\System\CurrentControlSet\Services\Tcpip\Parameters\Winsock","REPARSE","Desired Access: Read"
"6:46:01.7192907 AM","connect.EXE","912","RegOpenKey","HKLM\System\CurrentControlSet\Services\Tcpip\Parameters\Winsock","SUCCESS","Desired Access: Read"
"6:46:01.7192966 AM","connect.EXE","912","RegQueryValue","HKLM\System\CurrentControlSet\Services\Tcpip\Parameters\Winsock\MinSockaddrLength","SUCCESS","Type: REG_DWORD, Length: 4, Data: 16"
"6:46:01.7193012 AM","connect.EXE","912","RegQueryValue","HKLM\System\CurrentControlSet\Services\Tcpip\Parameters\Winsock\MaxSockaddrLength","SUCCESS","Type: REG_DWORD, Length: 4, Data: 16"
"6:46:01.7193054 AM","connect.EXE","912","RegQueryValue","HKLM\System\CurrentControlSet\Services\Tcpip\Parameters\Winsock\UseDelayedAcceptance","SUCCESS","Type: REG_DWORD, Length: 4, Data: 0"
"6:46:01.7193106 AM","connect.EXE","912","RegCloseKey","HKLM\System\CurrentControlSet\Services\Tcpip\Parameters\Winsock","SUCCESS",""
"6:46:01.7201104 AM","connect.EXE","912","RegCloseKey","HKLM\System\CurrentControlSet\Services\WinSock2\Parameters\Protocol_Catalog9","SUCCESS",""
"6:46:01.7201252 AM","connect.EXE","912","RegCloseKey","HKLM\System\CurrentControlSet\Services\WinSock2\Parameters\NameSpace_Catalog5","SUCCESS",""
"6:46:01.7202319 AM","connect.EXE","912","FASTIO_NETWORK_QUERY_OPEN","C:\Windows\System32\kernel.appcore.dll","FAST IO DISALLOWED",""
"6:46:01.7203969 AM","connect.EXE","912","IRP_MJ_CREATE","C:\Windows\System32\kernel.appcore.dll","SUCCESS","Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"6:46:01.7204185 AM","connect.EXE","912","FASTIO_QUERY_INFORMATION","C:\Windows\System32\kernel.appcore.dll","SUCCESS","Type: QueryBasicInformationFile, CreationTime: 11/21/2014 7:47:53 AM, LastAccessTime: 11/21/2014 7:47:53 AM, LastWriteTime: 11/21/2014 7:47:53 AM, ChangeTime: 12/4/2019 2:31:34 PM, FileAttributes: A"
"6:46:01.7204290 AM","connect.EXE","912","IRP_MJ_CLEANUP","C:\Windows\System32\kernel.appcore.dll","SUCCESS",""
"6:46:01.7204435 AM","connect.EXE","912","IRP_MJ_CLOSE","C:\Windows\System32\kernel.appcore.dll","SUCCESS",""
"6:46:01.7205422 AM","connect.EXE","912","IRP_MJ_CREATE","C:\Windows\System32\kernel.appcore.dll","SUCCESS","Desired Access: Read Data/List Directory, Execute/Traverse, Synchronize, Disposition: Open, Options: Synchronous IO Non-Alert, Non-Directory File, Attributes: n/a, ShareMode: Read, Delete, AllocationSize: n/a, OpenResult: Opened"
"6:46:01.7205920 AM","connect.EXE","912","FASTIO_ACQUIRE_FOR_SECTION_SYNCHRONIZATION","C:\Windows\System32\kernel.appcore.dll","FILE LOCKED WITH ONLY READERS","SyncType: SyncTypeCreateSection, PageProtection: "
"6:46:01.7206011 AM","connect.EXE","912","FASTIO_RELEASE_FOR_SECTION_SYNCHRONIZATION","C:\Windows\System32\kernel.appcore.dll","SUCCESS",""
"6:46:01.7206088 AM","connect.EXE","912","FASTIO_ACQUIRE_FOR_SECTION_SYNCHRONIZATION","C:\Windows\System32\kernel.appcore.dll","SUCCESS","SyncType: SyncTypeOther"
"6:46:01.7206139 AM","connect.EXE","912","FASTIO_RELEASE_FOR_SECTION_SYNCHRONIZATION","C:\Windows\System32\kernel.appcore.dll","SUCCESS",""
"6:46:01.7208406 AM","connect.EXE","912","IRP_MJ_READ","C:\Windows\System32\mswsock.dll","SUCCESS","Offset: 78,848, Length: 32,768, I/O Flags: Non-cached, Paging I/O, Synchronous Paging I/O, Priority: Normal"
"6:46:01.7208457 AM","connect.EXE","912","IRP_MJ_CLEANUP","C:\Windows\System32\kernel.appcore.dll","SUCCESS",""
"6:46:01.7208579 AM","connect.EXE","912","IRP_MJ_CLOSE","C:\Windows\System32\kernel.appcore.dll","SUCCESS",""
"6:46:01.7215400 AM","connect.EXE","912","RegOpenKey","HKLM\SYSTEM\CurrentControlSet\Control\Session Manager","REPARSE","Desired Access: Query Value, Enumerate Sub Keys"
"6:46:01.7215594 AM","connect.EXE","912","RegOpenKey","HKLM\System\CurrentControlSet\Control\Session Manager","SUCCESS","Desired Access: Query Value, Enumerate Sub Keys"
"6:46:01.7215765 AM","connect.EXE","912","RegQueryValue","HKLM\System\CurrentControlSet\Control\SESSION MANAGER\ResourcePolicies","NAME NOT FOUND","Length: 24"
"6:46:01.7215895 AM","connect.EXE","912","RegCloseKey","HKLM\System\CurrentControlSet\Control\SESSION MANAGER","SUCCESS",""
"6:46:01.7224784 AM","connect.EXE","912","IRP_MJ_CLEANUP","C:\src\postgresql\src\test\modules\connect","SUCCESS",""
"6:46:01.7224892 AM","connect.EXE","912","IRP_MJ_CLOSE","C:\src\postgresql\src\test\modules\connect","SUCCESS",""
"6:46:01.7225069 AM","connect.EXE","912","RegCloseKey","HKLM\System\CurrentControlSet\Control\SESSION MANAGER","SUCCESS",""
"6:46:01.7225785 AM","connect.EXE","912","RegCloseKey","HKLM\System\CurrentControlSet\Control\Nls\Sorting\Versions","SUCCESS",""
"6:46:01.7225825 AM","connect.EXE","912","RegCloseKey","HKLM","SUCCESS",""
"6:46:01.7496773 AM","perl.exe","2756","IRP_MJ_READ","C:\Users\Administrator\AppData\Local\Temp\IPC-Run.tmp\Win32io-002756-00053866","END OF FILE","Offset: 0, Length: 999,999, Priority: Normal"
"6:46:01.7497439 AM","perl.exe","2756","IRP_MJ_DEVICE_CONTROL","C:\Users\Administrator\AppData\Local\Temp\IPC-Run.tmp\Win32io-002756-00053866","FAST IO DISALLOWED","Control: 0x12043 (Device:0x1 Function:2064 Method: 3)"
