skip tests that hangs on Windows XP #31

chorny · 2014-12-07T13:22:00Z

No description provided.

mohawk2 · 2014-12-08T20:35:16Z

@sisyphus, @bulk88 - any comments on this? Looks good to me.

bulk88 · 2014-12-08T20:58:12Z

I havent deeply followed this bug. How do I reproduce the hang? I want make myself a C callstack of the hang, and possibly fix it.

chorny · 2014-12-08T21:04:50Z

@bulk88 Just run this test on Windows XP.

sisyphus · 2014-12-09T00:51:56Z

From: mohawk2

@sisyphus, @bulk88 - any comments on this? Looks good to me.

I was hoping to get to testing I::C on XP myself, but (for various reasons)
that might not happen for a while.
No objections from me - I don't have a better patch and something should
be done. Besides, it can easily be reverted/modified if future developments
dictate.

Cheers,
Rob

bulk88 · 2014-12-09T06:39:57Z

@bulk88 Just run this test on Windows XP.

C:\sources>perl 26fork.t
Can't locate TestInlineSetup.pm in @INC (you may need to install the TestInlineS
etup module) (@INC contains: test C:/perl521/site/lib C:/perl521/lib .) at 26for
k.t line 3.
BEGIN failed--compilation aborted at 26fork.t line 3.

C:\sources>

You need to be more specific.

mohawk2 · 2014-12-09T06:55:45Z

prove -lv test/26fork.t

in repo top-level dir.

bulk88 · 2014-12-09T07:26:04Z

process tree
parent->child
perl -x -S prove -lv test/26fork.tCWD C:\sources\inline-c-pm
->"C:\perl521\bin\perl.exe" test/26fork.tCWD C:\sources\inline-c-pm_Inline_26fork.4232\build_26fork_t_0cc7
->cmd.exe /x/d/c "c:\perl521\bin\perl.exe Makefile.PL > out.Makefile_PL 2>&1"*****CWD C:\sources\inline-c-pm_Inline_26fork.4232\build_26fork_t_0cc7
->c:\perl521\bin\perl.exe Makefile.PL *****CWD C:\sources\inline-c-pm_Inline_26fork.4232\build_26fork_t_0cc7
Curcop says
"c:/perl521/lib/ExtUtils/MakeMaker/Locale.pm"
line 50 which is

sub _init {
    if ($^O eq "MSWin32") {
    unless ($ENCODING_LOCALE) {
        # Try to obtain what the Windows ANSI code page is
        eval {
        unless (defined &GetACP) {
            require Win32::API;
            Win32::API->Import('kernel32', 'int GetACP()');
        };
        if (defined &GetACP) {
            my $cp = GetACP();
            $ENCODING_LOCALE = "cp$cp" if $cp;
        }
        };
    }

    unless ($ENCODING_CONSOLE_IN) {
        # If we have the Win32::Console module installed we can ask
        # it for the code set to use
        eval {
        require Win32::Console;
        my $cp = Win32::Console::InputCP();
        $ENCODING_CONSOLE_IN = "cp$cp" if $cp;
        $cp = Win32::Console::OutputCP();
        $ENCODING_CONSOLE_OUT = "cp$cp" if $cp;
        };
        # Invoking the 'chcp' program might also work
        if (!$ENCODING_CONSOLE_IN && (qx(chcp) || '') =~ /^Active code page: (\d+)/) {<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
        $ENCODING_CONSOLE_IN = "cp$1";
        }
    }
    }

the EUMM code git blames to Perl-Toolchain-Gang/ExtUtils-MakeMaker@01f64a6

Hi Mohawk!

ntdll.dll!_KiFastSystemCallRet@0()  
ntdll.dll!_NtReadFile@36()  + 0xc   
kernel32.dll!_ReadFile@20()  + 0x67 
msvcr71.dll!_read_lk(int fh=0x00000004, void * buf=0x0090c054, unsigned int cnt=0x00002000)  Line 154 + 0x15    C
msvcr71.dll!_read(int fh=0x00000004, void * buf=0x0090c054, unsigned int cnt=0x00002000)  Line 75 + 0xc C
perl521.dll!win32_read(int fd=0x00000004, void * buf=0x0090c054, unsigned int cnt=0x00002000)  Line 3351 + 0x12 C
perl521.dll!PerlLIORead(IPerlLIO * piPerl=0x00364154, int handle=0x00000004, void * buffer=0x0090c054, unsigned int count=0x00002000)  Line 1032 + 0x11 C
perl521.dll!PerlIOUnix_read(interpreter * my_perl=0x00366014, _PerlIO * * f=0x00c955ac, void * vbuf=0x0090c054, unsigned int count=0x00002000)  Line 2730 + 0x22    C
perl521.dll!Perl_PerlIO_read(interpreter * my_perl=0x00366014, _PerlIO * * f=0x00c955ac, void * vbuf=0x0090c054, unsigned int count=0x00002000)  Line 1591 + 0x3e   C
perl521.dll!PerlIOBuf_fill(interpreter * my_perl=0x00366014, _PerlIO * * f=0x008f5b94)  Line 4032 + 0x1b    C
perl521.dll!Perl_PerlIO_fill(interpreter * my_perl=0x00366014, _PerlIO * * f=0x008f5b94)  Line 1686 + 0x36  C
perl521.dll!PerlIOBase_read(interpreter * my_perl=0x00366014, _PerlIO * * f=0x008f5b94, void * vbuf=0x0012d5af, unsigned int count=0x00000001)  Line 2082 + 0xd C
perl521.dll!PerlIOBuf_read(interpreter * my_perl=0x00366014, _PerlIO * * f=0x008f5b94, void * vbuf=0x0012d5af, unsigned int count=0x00000001)  Line 4056 + 0x15 C
perl521.dll!Perl_PerlIO_read(interpreter * my_perl=0x00366014, _PerlIO * * f=0x008f5b94, void * vbuf=0x0012d5af, unsigned int count=0x00000001)  Line 1591 + 0x3e   C
perl521.dll!PerlIO_getc(_PerlIO * * f=0x008f5b94)  Line 4913 + 0x13 C
perl521.dll!Perl_sv_gets(interpreter * my_perl=0x00366014, sv * const sv=0x009e898c, _PerlIO * * const fp=0x008f5b94, long append=0x00000000)  Line 8531 + 0x9  C
perl521.dll!Perl_pp_backtick(interpreter * my_perl=0x00366014)  Line 321 + 0x1a C
perl521.dll!Perl_runops_debug(interpreter * my_perl=0x00366014)  Line 2242 + 0xd    C
perl521.dll!Perl_call_sv(interpreter * my_perl=0x00366014, sv * sv=0x008fd84c, volatile long flags=0x0000000d)  Line 2729 + 0x36    C
perl521.dll!Perl_call_list(interpreter * my_perl=0x00366014, long oldscope=0x00000002, av * paramList=0x008fd8ac)  Line 4840 + 0x5f C
perl521.dll!S_process_special_blocks(interpreter * my_perl=0x00366014, long floor=0x00000028, const char * const fullname=0x0090a728, gv * const gv=0x008fd8bc, cv * const cv=0x008fd84c)  Line 8683 + 0x17 C
perl521.dll!Perl_newATTRSUB_x(interpreter * my_perl=0x00366014, long floor=0x00000028, op * o=0x0090ac14, op * proto=0x00000000, void * attrs=0x28895317, op * block=0x0090abf4, char o_is_gv=0x00)  Line 8617 + 0x19   C
perl521.dll!Perl_utilize(interpreter * my_perl=0x00366014, int aver=0x00000001, long floor=0x00000028, op * version=0x00000000, op * idop=0x0090a828, op * arg=0x00000000)  Line 5844 + 0xb1    C
perl521.dll!Perl_yyparse(interpreter * my_perl=0x00366014, int gramtype=0x00000102)  Line 309 + 0x2c    C
perl521.dll!S_parse_body(interpreter * my_perl=0x00366014, char * * env=0x00365108, void (interpreter *)* xsinit=0x2872bb80)  Line 2270 + 0xe   C
perl521.dll!perl_parse(interpreter * my_perl=0x00366014, void (interpreter *)* xsinit=0x2872bb80, int argc=0x00000002, char * * argv=0x00362cf0, char * * env=0x00365108)  Line 1604 + 0x11 C
perl521.dll!RunPerl(int argc=0x00000002, char * * argv=0x00362cf0, char * * env=0x00365108)  Line 251 + 0x1a    C
perl.exe!main(int argc=0x00000002, char * * argv=0x00362cf0, char * * env=0x00363168)  Line 24 + 0x12   C
perl.exe!mainCRTStartup()  Line 398 + 0xe   C
kernel32.dll!_BaseProcessStart@4()  + 0x23

->cmd.exe /x/d/c chcp (end of tree)**CWD C:\sources\inline-c-pm_Inline_26fork.4232\build_26fork_t_0cc7\

ntdll.dll!_KiFastSystemCallRet@0()  
ntdll.dll!_ZwWaitForSingleObject@12()  + 0xc    
kernel32.dll!_WaitForSingleObjectEx@12()  + 0x8b    
kernel32.dll!_WaitForSingleObject@8()  + 0x12   
cmd.exe!_WaitProc@4()  + 0x18   
cmd.exe!_ExecPgm@28()  + 0x2f3  
cmd.exe!_ECWork@12()  + 0x6e    
cmd.exe!_ExtCom@4()  + 0x43 
cmd.exe!_FindFixAndRun@4()  + 0x4ac8    
cmd.exe!_Dispatch@8()  + 0x76   
cmd.exe!_main()  + 0xf9 
cmd.exe!_mainCRTStartup()  + 0x10e  
kernel32.dll!_BaseProcessStart@4()  + 0x23

update:
executing ->c:\perl521\bin\perl.exe Makefile.PL *****CWD C:\sources\inline-c-pm_Inline_26fork.4232\build_26fork_t_0cc7\ manually doesn't hang

neither does running cmd.exe /x/d/c "c:\perl521\bin\perl.exe Makefile.PL > out.Makefile_PL 2>&1" manually

manually running C:\sources\inline-c-pm>"C:\perl521\bin\perl.exe" test/26fork.t hangs

cmd.exe!_WaitProc@4 did the WaitForSingleObject on a process handle, using NTObjects tool, that process handle is "chcp.com"

Notice "Win32 Process" is NULL. There is no chcp in Process Explorer or Task Manager after the hang. For comparison, here is the parent of chcp (a cmd.exe process), being dumped, it does have a "Win32 Process" pointer. I almost want to say, somehow chcp "exited" (or sent a exit message) in CSRSS/Win32 layer land, yet continue to exist, atleast as a kernel handle, in kernel mode or user-mode. I'm not sure if chcp is still running or not or has a thread inside it. I can't explain it ATM. It sounds like I'll have to start looking through my kernel mem dump or find a tool that can see NT Native processes, not just win32 processes.

mohawk2 · 2014-12-09T07:37:02Z

Nice work. Why is chcp hanging?

bulk88 · 2014-12-09T18:43:44Z

I have a suspicion the freeze is because of the ".lock" file next to config-MSWin32-x86-multi-thread-5.021006 file and "build" dir. I thought I debugged a similar/identical kernel hang a few weeks ago but I can't find it on google. http://www.perlmonks.org/?node_id=1008652

http://msdn.microsoft.com/en-us/library/windows/desktop/aa365203%28v=vs.85%29.aspx

If a process terminates with a portion of a file locked or closes a file that has outstanding locks, the locks are unlocked by the operating system. However, the time it takes for the operating system to unlock these locks depends upon available system resources. Therefore, it is recommended that your process explicitly unlock all files it has locked when it terminates. If this is not done, access to these files may be denied if the operating system has not yet unlocked them.

5:55:27.5040065 AM  perl.exe    7264    5696    CreateFile  C:\sources\inline-c-pm\_Inline_26fork.7264\.lock    SUCCESS Desired Access: Generic Write, Read Attributes, Disposition: OverwriteIf, Options: Synchronous IO Non-Alert, Non-Directory File, Attributes: N, ShareMode: Read, Write, AllocationSize: 0, OpenResult: Created
5:55:27.5041323 AM  perl.exe    7264    2204    QueryOpen   C:\perl521\site\lib\overload.pm NAME NOT FOUND  
5:55:27.5042328 AM  perl.exe    7264    5696    QueryInformationVolume  C:\sources\inline-c-pm\_Inline_26fork.7264\.lock    SUCCESS VolumeCreationTime: 10/3/2013 7:36:19 AM, VolumeSerialNumber: 4C2D-0BFA, SupportsObjects: True, VolumeLabel: 
5:55:27.5042460 AM  perl.exe    7264    5696    QueryAllInformationFile C:\sources\inline-c-pm\_Inline_26fork.7264\.lock    BUFFER OVERFLOW CreationTime: 12/9/2014 5:55:27 AM, LastAccessTime: 12/9/2014 5:55:27 AM, LastWriteTime: 12/9/2014 5:55:27 AM, ChangeTime: 12/9/2014 5:55:27 AM, FileAttributes: A, AllocationSize: 0, EndOfFile: 0, NumberOfLinks: 1, DeletePending: False, Directory: False, IndexNumber: 0x12f0000000a3d92, EaSize: 0, Access: Generic Write, Read Attributes, Position: 0, Mode: Synchronous IO Non-Alert, AlignmentRequirement: Word
5:55:27.5042865 AM  perl.exe    7264    2204    CreateFile  C:\perl521\lib\overload.pm  SUCCESS Desired Access: Read Attributes, Synchronize, Disposition: Open, Options: Synchronous IO Non-Alert, Non-Directory File, Attributes: n/a, ShareMode: None, AllocationSize: n/a, OpenResult: Opened
5:55:27.5042923 AM  perl.exe    7264    5696    QueryInformationVolume  C:\sources\inline-c-pm\_Inline_26fork.7264\.lock    SUCCESS VolumeCreationTime: 10/3/2013 7:36:19 AM, VolumeSerialNumber: 4C2D-0BFA, SupportsObjects: True, VolumeLabel: 
5:55:27.5043029 AM  perl.exe    7264    5696    QueryAllInformationFile C:\sources\inline-c-pm\_Inline_26fork.7264\.lock    BUFFER OVERFLOW CreationTime: 12/9/2014 5:55:27 AM, LastAccessTime: 12/9/2014 5:55:27 AM, LastWriteTime: 12/9/2014 5:55:27 AM, ChangeTime: 12/9/2014 5:55:27 AM, FileAttributes: A, AllocationSize: 0, EndOfFile: 0, NumberOfLinks: 1, DeletePending: False, Directory: False, IndexNumber: 0x12f0000000a3d92, EaSize: 0, Access: Generic Write, Read Attributes, Position: 0, Mode: Synchronous IO Non-Alert, AlignmentRequirement: Word
5:55:27.5043091 AM  perl.exe    7264    2204    QueryInformationVolume  C:\perl521\lib\overload.pm  SUCCESS VolumeCreationTime: 10/3/2013 7:36:19 AM, VolumeSerialNumber: 4C2D-0BFA, SupportsObjects: True, VolumeLabel: 
5:55:27.5043203 AM  perl.exe    7264    2204    QueryAllInformationFile C:\perl521\lib\overload.pm  BUFFER OVERFLOW CreationTime: 5/28/2014 3:02:16 AM, LastAccessTime: 12/9/2014 5:55:27 AM, LastWriteTime: 10/31/2014 4:42:52 PM, ChangeTime: 11/13/2014 6:28:02 PM, FileAttributes: RA, AllocationSize: 53,248, EndOfFile: 52,628, NumberOfLinks: 1, DeletePending: False, Directory: False, IndexNumber: 0xb00000000b265, EaSize: 0, Access: Read Attributes, Synchronize, Position: 0, Mode: Synchronous IO Non-Alert, AlignmentRequirement: Word
5:55:27.5043278 AM  perl.exe    7264    5696    LockFile    C:\sources\inline-c-pm\_Inline_26fork.7264\.lock    SUCCESS Exclusive: True, Offset: 0, Length: 4,294,901,760, Fail Immediately: False

later on in the procmon log

5:55:28.4557392 AM  chcp.com    4028    568 RegOpenKey  HKLM\Software\Microsoft\Windows NT\CurrentVersion\Image File Execution Options\ntdll.dll    NAME NOT FOUND  Desired Access: Read
5:55:28.4557540 AM  chcp.com    4028    568 RegOpenKey  HKLM\Software\Microsoft\Windows NT\CurrentVersion\Image File Execution Options\kernel32.dll NAME NOT FOUND  Desired Access: Read
5:55:28.4560027 AM  chcp.com    4028    568 RegOpenKey  HKLM\Software\Microsoft\Windows NT\CurrentVersion\GRE_Initialize    SUCCESS Desired Access: Read
5:55:28.4560236 AM  chcp.com    4028    568 RegQueryValue   HKLM\SOFTWARE\Microsoft\Windows NT\CurrentVersion\GRE_Initialize\DisableMetaFiles   NAME NOT FOUND  Length: 20
5:55:28.4560443 AM  chcp.com    4028    568 RegCloseKey HKLM\SOFTWARE\Microsoft\Windows NT\CurrentVersion\GRE_Initialize    SUCCESS 
5:55:28.4561102 AM  chcp.com    4028    568 Thread Exit     SUCCESS Thread ID: 568, User Time: 0.0000000, Kernel Time: 0.0156250
5:55:28.4578261 AM  chcp.com    4028    568 Process Exit        SUCCESS Exit Status: 0, User Time: 0.0156250 seconds, Kernel Time: 0.0156250 seconds, Private Bytes: 311,296, Peak Private Bytes: 323,584, Working Set: 1,261,568, Peak Working Set: 1,265,664
5:55:28.4578373 AM  chcp.com    4028    568 CloseFile   C:\sources\inline-c-pm\_Inline_26fork.7264\build\_26fork_t_0cc7 SUCCESS 
5:55:28.4578618 AM  chcp.com    4028    568 UnlockFileAll   C:\sources\inline-c-pm\_Inline_26fork.7264\.lock    SUCCESS Offset: 0, Length: 0
1:33:16.0104963 PM  cmd.exe 7568    2336    Thread Create       SUCCESS Thread ID: 4628
1:33:16.0105782 PM  perl.exe    2740    2336    Thread Create       SUCCESS Thread ID: 5640
1:33:16.0106335 PM  cmd.exe 2216    2336    Thread Create       SUCCESS Thread ID: 6440

Notice chcp unlocking the file in kernel mode (since user mode already ended because of the process exit line) is the last thing the process did, or tried to do.

I'll try to confirm this some way.

bulk88 · 2014-12-10T00:01:25Z

I ****ing swear I debugged it couple months ago. That is how I knew it was the .lock file. I dont know why I can't find any trace of my research on google, unless I X-ed it all out and never saved it and forgot about it like a fool. So chcp is hanged in kernel mode in ExitProcess. It already unregistered from the Win32 layer so that is why it doesn't appear in the vast majority of process manager tools. So it is now a "zombie process". It has no user mode threads (not from the view of user mode debuggers but it has a user mode C stack still allocated).

0: kd> k
  *** Stack trace for last set context - .thread/.cxr resets it
ChildEBP RetAddr  
b630ab04 804e1bf2 nt!KiSwapContext+0x2f
b630ab10 804e1c3e nt!KiSwapThread+0x8a
b630ab38 805927ba nt!KeWaitForSingleObject+0x1c2
b630ab60 805f20b8 nt!IopAcquireFileObjectLock+0x3e
b630aba0 8056f831 nt!IopCloseFile+0x17a
b630abd4 8056f984 nt!ObpDecrementHandleCount+0xd8
b630abfc 805939b2 nt!ObpCloseHandleTableEntry+0x14d
b630ac1c 805931ee nt!ObpCloseHandleProcedure+0x1f
b630ac3c 8059395e nt!ExSweepHandleTable+0x3b
b630ac68 805930e3 nt!ObKillProcess+0x5c
b630ad08 80575ba2 nt!PspExitThread+0x5e9
b630ad28 8059351d nt!PspTerminateThreadByPointer+0x52
b630ad54 804dd99f nt!NtTerminateProcess+0x118
b630ad54 7c90e514 nt!KiFastCallEntry+0xfc
0006fd44 7c90de7a ntdll!KiFastSystemCallRet
0006fd48 7c81cace ntdll!NtTerminateProcess+0xc
0006fe44 7c81cb26 kernel32!_ExitProcess+0x62
0006fe64 0100166d kernel32!ExitProcess+0x14
0006fe74 010016cc chcp!CHCP::Chcp+0x44
0006ff44 01001800 chcp!main+0x50
0006ffc0 7c817077 chcp!mainCRTStartup+0x125
0006fff0 00000000 kernel32!BaseProcessStart+0x23

So the question is, what made the .lock file? Did perl uses strictly p5p controlled code or an XS module to make that .lock file? I assume the handle for the .lock file was "inherited" by all child procs in the tree as shown in process explorer. When NT kernel tries to close all open handles in chcp proces, closing 1 handle hangs as shown. Note this is kernel mode, so whether the process is ever aware (AKA the handle number is in the process's user mode memory) that handle is open in its process is irrelevant for the kernel. This might be a bug in how perl marks handles to be "inherited" in CreateProcess child procs. IDK what happens on POSIX to comment what Win32 perl should be doing. I will next try to figure out the lock owner PID.

mohawk2 · 2014-12-10T00:23:37Z

The lock file is in order to implement what is being tested by test 26: deconflicting access to the DID directory (eg _Inline). It's happening in Inline and also in Inline::C.

bulk88 · 2014-12-10T01:06:53Z

While looking for what could have locked the .lock file, I noticed something in the test/26fork.t process.

child thread
    ntdll.dll!_KiFastSystemCallRet@0()  
    ntdll.dll!_NtLockFile@40()  + 0xc   
    kernel32.dll!_LockFileEx@24()  + 0x82   
    perl521.dll!win32_flock(int fd=4, int oper=2)  Line 2494 + 0x19 C
    perl521.dll!PerlLIOFlock(IPerlLIO * piPerl=0x009efb1c, int fd=4, int oper=2)  Line 965 + 0xd    C
    perl521.dll!Perl_pp_flock(interpreter * my_perl=0x011a20d4)  Line 2400 + 0x2b   C
    perl521.dll!Perl_runops_debug(interpreter * my_perl=0x011a20d4)  Line 2242 + 0xd    C
    perl521.dll!win32_start_child(void * arg=0x011a20d4)  Line 1748 + 0xd   C
    kernel32.dll!_BaseThreadStart@8()  + 0x37   

parent thread
    ntdll.dll!_KiFastSystemCallRet@0()  
    ntdll.dll!_ZwWaitForMultipleObjects@20()  + 0xc 
    kernel32.dll!_WaitForMultipleObjectsEx@20()  - 0x48 
    user32.dll!_RealMsgWaitForMultipleObjectsEx@20()  + 0xd9    
    user32.dll!_MsgWaitForMultipleObjects@20()  + 0x1f  
    perl521.dll!win32_msgwait(interpreter * my_perl=0x00366014, unsigned long count=1, void * * handles=0x0012fb10, unsigned long timeout=4294967295, unsigned long * resultp=0x00000000)  Line 2241 + 0x1f C
    perl521.dll!do_spawnvp_handles(int mode=0, const char * cmdname=0x01636c5c, const char * const * argv=0x01c7af6c, const int * handles=0x00000000)  Line 3860 + 0x19 C
    perl521.dll!win32_spawnvp(int mode=0, const char * cmdname=0x01636c5c, const char * const * argv=0x01c7af6c)  Line 3715 + 0x13  C
    perl521.dll!do_spawn2_handles(interpreter * my_perl=0x00366014, const char * cmd=0x01cd41bc, int exectype=2, const int * handles=0x00000000)  Line 749 + 0x11   C
    perl521.dll!do_spawn2(interpreter * my_perl=0x00366014, const char * cmd=0x01cd41bc, int exectype=2)  Line 687 + 0x13   C
    perl521.dll!Perl_do_spawn(interpreter * my_perl=0x00366014, char * cmd=0x01cd41bc)  Line 785 + 0xf  C
    perl521.dll!Perl_pp_system(interpreter * my_perl=0x00366014)  Line 4360 + 0x75  C
    perl521.dll!Perl_runops_debug(interpreter * my_perl=0x00366014)  Line 2242 + 0xd    C
    perl521.dll!S_run_body(interpreter * my_perl=0x00366014, long oldscope=1)  Line 2420 + 0xd  C
    perl521.dll!perl_run(interpreter * my_perl=0x00366014)  Line 2346   C
    perl521.dll!RunPerl(int argc=2, char * * argv=0x00362c68, char * * env=0x00365238)  Line 258 + 0x9  C
    perl.exe!main(int argc=2, char * * argv=0x00362c68, char * * env=0x00363108)  Line 24 + 0x12    C
    perl.exe!mainCRTStartup()  Line 398 + 0xe   C
    kernel32.dll!_BaseProcessStart@4()  + 0x23

Child thread is at curcop "C:\sources\inline-c-pm\lib/Inline/C.pm"

#==============================================================================
# Parse and compile C code
#==============================================================================
my $total_build_time;
sub build {
    my $o = shift;

    if ($o->{CONFIG}{BUILD_TIMERS}) {
        eval {require Time::HiRes};
        croak "You need Time::HiRes for BUILD_TIMERS option:\n$@" if $@;
        $total_build_time = Time::HiRes::time();
    }
    my $file = File::Spec->catfile($o->{API}{directory},'.lock');
    open my $lockfh, '>', $file or die "lockfile $file: $!";
    flock($lockfh, LOCK_EX) or die "flock: $!\n" if $^O !~ /^VMS|riscos|VOS$/;<<<<<<<<<<<<<<<<<<
    $o->mkpath($o->{API}{build_dir});
    $o->call('preprocess', 'Build Preprocess');
    $o->call('parse', 'Build Parse');
    $o->call('write_XS', 'Build Glue 1');
    $o->call('write_Inline_headers', 'Build Glue 2');
    $o->call('write_Makefile_PL', 'Build Glue 3');
    $o->call('compile', 'Build Compile');
    flock($lockfh, LOCK_UN) if $^O !~ /^VMS|riscos|VOS$/;
    if ($o->{CONFIG}{BUILD_TIMERS}) {
        $total_build_time = Time::HiRes::time() - $total_build_time;
        printf STDERR "Total Build Time: %5.4f secs\n", $total_build_time;
    }
}

kernel mode side of child thread stack

0: kd> kb
  *** Stack trace for last set context - .thread/.cxr resets it
ChildEBP RetAddr  Args to Child              
b5bb3c38 804e1bf2 896de428 896de3b8 804e1c3e nt!KiSwapContext+0x2f
b5bb3c44 804e1c3e 00000103 00000000 89af0d98 nt!KiSwapThread+0x8a
b5bb3c6c 805830a9 00000001 00000000 89966b01 nt!KeWaitForSingleObject+0x1c2
b5bb3c94 805e0887 8ad42020 00000103 89966bf8 nt!IopSynchronousServiceTail+0xe8
b5bb3d34 804dd99f 00000740 00000000 00000000 nt!NtLockFile+0x36d
b5bb3d34 7c90e514 00000740 00000000 00000000 nt!KiFastCallEntry+0xfc
0192fe78 00000000 00000000 00000000 00000000 ntdll!KiFastSystemCallRet

Notice 89966bf8 into IopSynchronousServiceTail. That is the file object. So now the question is, what is going on with the IRP and can I figure out what is blocking the IRP from completing. Device object/"driver" that got the IRP is

0: kd> dt ntdll!_DEVICE_OBJECT 0x8ad42020
   +0x000 Type             : 0n3
   +0x002 Size             : 0x860
   +0x004 ReferenceCount   : 0n0
   +0x008 DriverObject     : 0x8ad412e8 _DRIVER_OBJECT
   +0x00c NextDevice       : 0x8ad45be0 _DEVICE_OBJECT
   +0x010 AttachedDevice   : 0x88ce74f8 _DEVICE_OBJECT
   +0x014 CurrentIrp       : (null) 
   +0x018 Timer            : (null) 
   +0x01c Flags            : 0
   +0x020 Characteristics  : 0
   +0x024 Vpb              : (null) 
   +0x028 DeviceExtension  : 0x8ad420d8 Void
   +0x02c DeviceType       : 8
   +0x030 StackSize        : 14 ''
   +0x034 Queue            : __unnamed
   +0x05c AlignmentRequirement : 1
   +0x060 DeviceQueue      : _KDEVICE_QUEUE
   +0x074 Dpc              : _KDPC
   +0x094 ActiveThreadCount : 0
   +0x098 SecurityDescriptor : (null) 
   +0x09c DeviceLock       : _KEVENT
   +0x0ac SectorSize       : 0x200
   +0x0ae Spare1           : 1
   +0x0b0 DeviceObjectExtension : 0x8ad42880 _DEVOBJ_EXTENSION
   +0x0b4 Reserved         : (null) 
0: kd> dt ntdll!_DRIVER_OBJECT 0x8ad412e8
   +0x000 Type             : 0n4
   +0x002 Size             : 0n168
   +0x004 DeviceObject     : 0x8ad42020 _DEVICE_OBJECT
   +0x008 Flags            : 0x92
   +0x00c DriverStart      : 0xf7b52000 Void
   +0x010 DriverSize       : 0x8c600
   +0x014 DriverSection    : 0x8add78b0 Void
   +0x018 DriverExtension  : 0x8ad41390 _DRIVER_EXTENSION
   +0x01c DriverName       : _UNICODE_STRING "\FileSystem\Ntfs"
   +0x024 HardwareDatabase : 0x8069b210 _UNICODE_STRING "\REGISTRY\MACHINE\HARDWARE\DESCRIPTION\SYSTEM"
   +0x028 FastIoDispatch   : 0xf7b719a0 _FAST_IO_DISPATCH
   +0x02c DriverInit       : 0xf7bd7384     long  Ntfs!GsDriverEntry+0
   +0x030 DriverStartIo    : (null) 
   +0x034 DriverUnload     : (null) 
   +0x038 MajorFunction    : [28] 0xf7b77e01     long  Ntfs!NtfsFsdCreate+0

Not very interesting.

update:
Im reading http://www.agent31.eu/2007/01/perl-windows-and-file-locking.html

update:
I assume the 2 separate .lock file handles, are, one are the parent psuedo-fork that holds the lock (kernel pointer 0x89920218/handle 744), the other is the child psudofork trying to get the lock and blocking (kernel pointer 0x89966bf8 /handle 740) with pp_flock/LockFileEx. Remember the zombie chcp is blocked on kernel pointer 0x89966bf8. All the child procs of 26fork.t perl.exe have these 2 handles in their processes.

So the bug is, in psuedofork Win32 perl, when you backticks (or I guess system() also), the child proc inherits the handles of all psuedo-procs. In this case, the child process is launched from main thread/psuedoproc that holds .lock and the child inherits that , the child proc also inherits the other .lock blocked in flock handle. At child proc exit, in kernel mode, the child proc blocks on the "other" .lock handle blocked in flock. The block then propagates to the main psuedoproc which is waiting for child proc to exit. Deadlock.

lock dependency chain

main psuedoproc ->chcp->child psuedoproc---
^-----------------------------------------|

On unix perl, the handle in the child psuedoproc (eghh, terms) would never be inherited by chcp process, so chcp wouldn't block, and the main psuedoproc wouldn't block.

I have to manipulate inheritance settings now and see if it fixes the hang.

bulk88 · 2014-12-10T05:23:16Z

The bug isolated into a test case

use Fcntl ':flock';
my $file = 'the_lock';

$^F = -1;
if(fork == 0){
    sleep 1;
    open my $lockfh, '>', $file or die "lockfile $file: $!";
    flock($lockfh, LOCK_EX) or die "flock: $!\n";
    flock($lockfh, LOCK_UN);
}
open my $lockfh, '>', $file or die "lockfile $file: $!";
flock($lockfh, LOCK_EX) or die "flock: $!\n";
sleep 2;
system($^O eq 'MSWin32' ? 'dir' : 'ls');
flock($lockfh, LOCK_UN);

filed as https://rt.perl.org/Ticket/Display.html?id=123402

See ingydotnet#31 for bug description.

sisyphus · 2014-12-10T07:21:03Z

From: bulk88

filed as https://rt.perl.org/Ticket/Display.html?id=123402

Your demo works fine for me on Windows 7, perls 5.16.0 and 5.21.6. No
hanging at all.

This is perl 5, version 16, subversion 0 (v5.16.0) built for
MSWin32-x86-multi-thread
&
This is perl 5, version 21, subversion 6 (v5.21.6) built for
MSWin32-x86-multi-thread-64int.

Cheers,
Rob

See ingydotnet#31 for bug description. Even with this fix, the tests randomly fail due to a race condition where the .dll can not be deleted from disk while still loaded in a process.

See ingydotnet#31 for bug description.

See #31 for bug description.

ingydotnet · 2014-12-27T20:31:07Z

Fixed

skip tests that hangs on Windows XP

6bd908a

bulk88 added a commit to bulk88/inline-c-pm that referenced this pull request Dec 10, 2014

fix hang in test/26fork.t on Win32

1d9ae60

See ingydotnet#31 for bug description.

bulk88 mentioned this pull request Dec 10, 2014

fix hang in test/26fork.t on Win32 #32

Closed

bulk88 added a commit to bulk88/inline-c-pm that referenced this pull request Dec 10, 2014

fix hang in test/26fork.t on Win32

678093d

See ingydotnet#31 for bug description.

bulk88 added a commit to bulk88/inline-c-pm that referenced this pull request Dec 10, 2014

fix hang in test/26fork.t on Win32

74035c1

See ingydotnet#31 for bug description.

bulk88 added a commit to bulk88/inline-c-pm that referenced this pull request Dec 10, 2014

fix hang in test/26fork.t on Win32

92df031

See ingydotnet#31 for bug description.

ingydotnet pushed a commit that referenced this pull request Dec 27, 2014

fix hang in test/26fork.t on Win32

f22516c

See #31 for bug description.

ingydotnet pushed a commit that referenced this pull request Dec 27, 2014

fix hang in test/26fork.t on Win32

6e66d45

See #31 for bug description.

ingydotnet closed this Dec 27, 2014

p5pRT mentioned this pull request Oct 19, 2019

every OS child procs hangs forever if there is a blocked flock() in a win32 psuedofork Perl/perl5#14320

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

skip tests that hangs on Windows XP #31

skip tests that hangs on Windows XP #31

chorny commented Dec 7, 2014

mohawk2 commented Dec 8, 2014

bulk88 commented Dec 8, 2014

chorny commented Dec 8, 2014

sisyphus commented Dec 9, 2014

bulk88 commented Dec 9, 2014

mohawk2 commented Dec 9, 2014

bulk88 commented Dec 9, 2014

mohawk2 commented Dec 9, 2014

bulk88 commented Dec 9, 2014

bulk88 commented Dec 10, 2014

mohawk2 commented Dec 10, 2014

bulk88 commented Dec 10, 2014

bulk88 commented Dec 10, 2014

sisyphus commented Dec 10, 2014

ingydotnet commented Dec 27, 2014

skip tests that hangs on Windows XP #31

skip tests that hangs on Windows XP #31

Conversation

chorny commented Dec 7, 2014

mohawk2 commented Dec 8, 2014

bulk88 commented Dec 8, 2014

chorny commented Dec 8, 2014

sisyphus commented Dec 9, 2014

bulk88 commented Dec 9, 2014

mohawk2 commented Dec 9, 2014

bulk88 commented Dec 9, 2014

mohawk2 commented Dec 9, 2014

bulk88 commented Dec 9, 2014

bulk88 commented Dec 10, 2014

mohawk2 commented Dec 10, 2014

bulk88 commented Dec 10, 2014

bulk88 commented Dec 10, 2014

sisyphus commented Dec 10, 2014

ingydotnet commented Dec 27, 2014