Subject: Re: Sometimes the output to the stdout in Windows disappears
To: Tom Lane <tgl@sss.pgh.pa.us>
Cc: Victor Spirin <v.spirin@postgrespro.ru>,
 pgsql-hackers@lists.postgresql.org
References: <ac976d8c-03df-d6b8-025c-15a2de8d9af1@postgrespro.ru>
 <4124040.1598898684@sss.pgh.pa.us>
 <b92a7e09-9a60-d76b-e226-7e191fdc6f34@postgrespro.ru>
 <855416.1600022228@sss.pgh.pa.us>
 <ee02eaa2-03f7-74ea-bbdf-3196e506bae3@gmail.com>
 <4156857.1602865112@sss.pgh.pa.us>
From: Alexander Lakhin <exclusion@gmail.com>
Message-ID: <b32688da-fafc-bbf6-b786-2dd7d0a4d578@gmail.com>
Date: Sat, 17 Oct 2020 11:00:02 +0300
User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:68.0) Gecko/20100101
 Thunderbird/68.10.0
MIME-Version: 1.0
In-Reply-To: <4156857.1602865112@sss.pgh.pa.us>
Content-Type: multipart/mixed;
 boundary="------------AE6AC379E65277DADFD75612"
Content-Language: en-US
Precedence: bulk

This is a multi-part message in MIME format.
--------------AE6AC379E65277DADFD75612
Content-Type: multipart/alternative;
 boundary="------------7AA49A315A1CB82265ADF78B"


--------------7AA49A315A1CB82265ADF78B
Content-Type: text/plain; charset=utf-8
Content-Transfer-Encoding: 8bit

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

--------------7AA49A315A1CB82265ADF78B
Content-Type: text/html; charset=utf-8
Content-Transfer-Encoding: 8bit

<html>
  <head>
    <meta http-equiv="Content-Type" content="text/html; charset=UTF-8">
  </head>
  <body>
    <div class="moz-cite-prefix">16.10.2020 19:18, Tom Lane wrote:<br>
    </div>
    <blockquote type="cite" cite="mid:4156857.1602865112@sss.pgh.pa.us">Oh,
      very interesting.
      <pre class="moz-quote-pre" wrap="">
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.)</pre>
    </blockquote>
    stderr is affected too. Just replacing stdout with stderr in
    connect.c and 000_connect.pl gives the same result.<br>
    <br>
    Moreover, the following modification:<br>
    ...<br>
        outfile = fopen("out", "w");<br>
    ...<br>
        fprintf(stdout, "stdout test\n");<br>
        fprintf(stderr, "stderr test\n");<br>
        fprintf(outfile, "outfile test\n");<br>
        WSACleanup();<br>
    ...<br>
    <br>
    ---<br>
    for (my $i =0; $i &lt; 100000; $i++) {<br>
        unlink('out');<br>
        IPC::Run::run(\@cmd, '&gt;', \$stdout, '2&gt;', \$stderr);<br>
        open(my $fh, '&lt;', 'out') or die $!;<br>
        my $fileout = &lt;$fh&gt;;<br>
        ok(defined $fileout &amp;&amp; $fileout ne '');<br>
        close($fh);<br>
    }<br>
    <br>
    detects similar failures too. (On a fail the out file exists but has
    zero size.)<br>
    <br>
    <blockquote type="cite" cite="mid:4156857.1602865112@sss.pgh.pa.us">
      <pre class="moz-quote-pre" wrap="">2. Does an fflush() just before, or just after, WSACleanup() fix it?</pre>
    </blockquote>
    "fflush(NULL);" just before or after WSACleanup() fixes things.<br>
    <br>
    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.<br>
    <br>
    <blockquote type="cite" cite="mid:4156857.1602865112@sss.pgh.pa.us">
      <pre class="moz-quote-pre" wrap="">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.</pre>
    </blockquote>
    But now we see that the WSACleanup call is a global thing by itself.
    <blockquote type="cite" cite="mid:4156857.1602865112@sss.pgh.pa.us">
      <pre class="moz-quote-pre" wrap="">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.</pre>
    </blockquote>
    What bothers me is:<br>
    <blockquote>There must be a call to
      <b>WSACleanup</b> for each successful call to
      <a
href="https://docs.microsoft.com/en-us/windows/desktop/api/winsock/nf-winsock-wsastartup"
        data-linktype="absolute-path">WSAStartup</a>. Only the final
      <b>WSACleanup</b> function call performs the actual cleanup. The
      preceding calls simply decrement an internal reference count in
      the WS2_32.DLL.<br>
    </blockquote>
    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.)<br>
    But may be it's a way better than to have a confirmed risk of losing
    data.<br>
    <br>
    Best regards,<br>
    Alexander<br>
  </body>
</html>

--------------7AA49A315A1CB82265ADF78B--

--------------AE6AC379E65277DADFD75612
Content-Type: text/csv; charset=UTF-8;
 name="Logfile-OK.CSV"
Content-Transfer-Encoding: 8bit
Content-Disposition: attachment;
 filename="Logfile-OK.CSV"

﻿"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)"

--------------AE6AC379E65277DADFD75612
Content-Type: text/csv; charset=UTF-8;
 name="Logfile-FAIL.CSV"
Content-Transfer-Encoding: 8bit
Content-Disposition: attachment;
 filename="Logfile-FAIL.CSV"

﻿"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)"

--------------AE6AC379E65277DADFD75612--