Bug 5958 - testBlockingFibonacciClone(frysk.proc.live.TestTaskObserverBlocked)java.lang.RuntimeException: {frysk.proc.live.LinuxPtraceTask@37d83689,pid=3716,tid=3717,state=detached} in state "detached" did not handle handleStoppedEvent SIGSTOP(19)
Summary: testBlockingFibonacciClone(frysk.proc.live.TestTaskObserverBlocked)java.lang....
Status: RESOLVED FIXED
Alias: None
Product: frysk
Classification: Unclassified
Component: general (show other bugs)
Version: unspecified
: P2 normal
Target Milestone: ---
Assignee: Andrew Cagney
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2008-03-18 15:22 UTC by Andrew Cagney
Modified: 2008-03-18 19:27 UTC (History)
0 users

See Also:
Host:
Target:
Build:
Last reconfirmed:


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Andrew Cagney 2008-03-18 15:22:35 UTC
testBlockingFibonacciClone(frysk.proc.live.TestTaskObserverBlocked)java.lang.RuntimeException:
{frysk.proc.live.LinuxPtraceTask@37d83689,pid=3716,tid=3717,state=detached} in
state "detached" did not handle handleStoppedEvent SIGSTOP(19)
   at frysk.proc.live.State.unhandled(TestRunner)
   at frysk.proc.live.LinuxPtraceTaskState.handleStoppedEvent(TestRunner)
   at frysk.proc.live.LinuxPtraceTask.processStoppedEvent(TestRunner)
   at frysk.proc.live.LinuxWaitBuilder.stopped(TestRunner)
   at frysk.sys.Wait.wait(TestRunner)
   at frysk.sys.Wait.wait(TestRunner)
   at frysk.event.WaitEventLoop.block(TestRunner)
   at frysk.event.EventLoop.runEventLoop(TestRunner)
   at frysk.event.EventLoop.runPolling(TestRunner)
   at frysk.testbed.TestLib.assertRunUntilStop(TestRunner)
   at frysk.testbed.TestLib.assertRunUntilStop(TestRunner)
   at frysk.proc.live.TestTaskObserverBlocked.access$2(TestRunner)
   at frysk.proc.live.TestTaskObserverBlocked$BlockingFibonacci.<init>(TestRunner)
   at frysk.proc.live.TestTaskObserverBlocked$1$CloneFibonacci.<init>(TestRunner)
   at frysk.proc.live.TestTaskObserverBlocked.testBlockingFibonacciClone(TestRunner)
   at frysk.junit.Runner.runCases(TestRunner)
   at frysk.junit.Runner.runTestCases(TestRunner)
   at TestRunner.main(TestRunner)
Comment 1 Andrew Cagney 2008-03-18 15:27:01 UTC
Here's the relevant log:

The attached process execs:

00:00:00.040 9640.9640 frysk.proc.live.LinuxPtraceTaskState: handleExecedEvent
<<{frysk.proc.live.LinuxPtraceTask@37d36981,pid=9643,tid=9643,state=ru
nning}>>
00:00:00.040 9640.9640
[{frysk.proc.live.LinuxPtraceTask@37d36981,pid=9643,tid=9643,state=running}]:
clearIsa
00:00:00.040 9640.9640
[{frysk.proc.live.LinuxPtraceTask@37d36981,pid=9643,tid=9643,state=running}]:
initializeAttachedState
00:00:00.040 9640.9640
[{frysk.proc.live.LinuxPtraceTask@37d36981,pid=9643,tid=9643,state=blockedInExecSyscall}]:
requestAddClonedObserver
00:00:00.040 9640.9640
[{frysk.proc.live.LinuxPtraceProc@37d2dea1,pid=9643,state=running}]:
requestAddObservation
00:00:00.040 9640.9640
[{frysk.proc.live.LinuxPtraceTask@37d36981,pid=9643,tid=9643,state=blockedInExecSyscall}]:
requestDeleteExecedObserver
00:00:00.040 9640.9640 frysk.proc.live.LinuxPtraceProcState:
handleAddObservation
<<{frysk.proc.live.LinuxPtraceProc@37d2dea1,pid=9643,state=running}
>>
00:00:00.040 9640.9640 frysk.proc.live.LinuxPtraceTaskState:
handleAddObservation
<<{frysk.proc.live.LinuxPtraceTask@37d36981,pid=9643,tid=9643,state
=blockedInExecSyscall}>>
00:00:00.040 9640.9640 frysk.proc.live.LinuxPtraceProcState:
handleDeleteObservation
<<{frysk.proc.live.LinuxPtraceProc@37d2dea1,pid=9643,state=runni
ng}>>
00:00:00.040 9640.9640 frysk.proc.live.LinuxPtraceTaskState:
handleDeleteObservation
<<{frysk.proc.live.LinuxPtraceTask@37d36981,pid=9643,tid=9643,st
ate=blockedInExecSyscall}>>
00:00:00.040 9640.9640 frysk.proc.live.LinuxPtraceTaskState: handleUnbloc
<<{frysk.proc.live.LinuxPtraceTask@37d36981,pid=9643,tid=9643,state=blocked
InExecSyscall}>> observer
<<frysk.testbed.DaemonBlockedAtEntry$ExecBlockingObserver@37262741[{frysk.proc.live.LinuxPtraceTask@37d36981,pid=9643,tid=9
643,state=blockedInExecSyscall}][{frysk.proc.live.LinuxPtraceTask@37d36981,pid=9643,tid=9643,state=blockedInExecSyscall}]>>
00:00:00.040 9640.9640 frysk.proc.live.LinuxPtraceTaskState: sendContinue
<<{frysk.proc.live.LinuxPtraceTask@37d36981,pid=9643,tid=9643,state=blocked
InExecSyscall}>> breakpoint <<null>>
00:00:00.040 9640.9640
[{frysk.proc.live.LinuxPtraceTask@37d36981,pid=9643,tid=9643,state=blockedInExecSyscall}]:
sendContinue

meanwhile, a process scan has found a new _main_ process in /proc and is
creating it:

00:00:00.041 9640.9640
[{frysk.proc.live.LinuxPtraceProc@37d2df01,pid=1,state=detached}]: add(Proc) --
a child process
00:00:00.041 9640.9640
[{frysk.proc.live.LinuxPtraceProc@37d2de41,pid=9644,state=<null>}]: new - create
unattached running proc
java.lang.RuntimeException
   at frysk.proc.live.LinuxPtraceProc.<init>(TestRunner)
   at frysk.proc.live.LinuxPtraceHost$ProcChanges.update(TestRunner)
   at frysk.proc.live.LinuxPtraceHost$4.build(TestRunner)
   at frysk.sys.proc.ProcBuilder.scan(TestRunner)
   at frysk.sys.proc.ProcBuilder.construct(TestRunner)
   at frysk.sys.proc.ProcBuilder.construct(TestRunner)
   at frysk.proc.live.LinuxPtraceHost$3.execute(TestRunner)
   at frysk.event.EventLoop.runEventLoop(TestRunner)
   at frysk.event.EventLoop.runPolling(TestRunner)
   at frysk.testbed.TestLib.assertRunUntilStop(TestRunner)
   at frysk.testbed.TestLib.assertRunUntilStop(TestRunner)
   at frysk.testbed.TestLib.assertRunToFindProc(TestRunner)
   at frysk.testbed.Offspring.assertRunToFindProc(TestRunner)
   at frysk.testbed.StopEventLoopWhenProcTerminated.<init>(TestRunner)

unfortunatly, what the core thought was a new independent process is in fact a
new task (clone) of the process being traced; and here comes the events for that
attached task:

00:00:00.051 9640.9640 frysk.proc.live.LinuxPtraceProcState: initial false
00:00:00.051 9640.9640 frysk.proc.Task: new -- create unattached
00:00:00.051 9640.9640
[{frysk.proc.live.LinuxPtraceTask@37d36981,pid=9643,tid=9643,state=running}]:
requestAddTerminatedObserver
00:00:00.051 9640.9640
[{frysk.proc.live.LinuxPtraceProc@37d2dea1,pid=9643,state=running}]:
requestAddObservation
00:00:00.051 9640.9640 frysk.proc.live.LinuxPtraceProcState:
handleAddObservation
<<{frysk.proc.live.LinuxPtraceProc@37d2dea1,pid=9643,state=running}>>
00:00:00.051 9640.9640 frysk.proc.live.LinuxPtraceTaskState:
handleAddObservation
<<{frysk.proc.live.LinuxPtraceTask@37d36981,pid=9643,tid=9643,state=running}>>
00:00:00.051 9640.9640 [frysk.proc.live.LinuxWaitBuilder@37262981]: stopped <<9644>>
00:00:00.052 9640.9640
[{frysk.proc.live.LinuxPtraceTask@37d36689,pid=9643,tid=9644,state=detached}]:
stoppedEvent <<SIGSTOP(19)>>
00:00:00.052 9640.9640 frysk.proc.live.State: unhandled
<<{frysk.proc.live.LinuxPtraceTask@37d36689,pid=9643,tid=9644,state=detached}>>
event "handleStoppedEvent SIGSTOP(19)"
ERROR
  java.lang.RuntimeException:
{frysk.proc.live.LinuxPtraceTask@37d36689,pid=9643,tid=9644,state=detached} in
state "detached" did not handle handleStoppedEvent SIGSTOP(19)

since the core thought the process wasn't attached, when it was there's a panic
Comment 2 Andrew Cagney 2008-03-18 19:27:20 UTC
commit 60b670aadfefc72320d0fd948f1d492edc641aa9
Author: Andrew Cagney <cagney@redhat.com>
Date:   Tue Mar 18 15:24:57 2008 -0400

    Stop Task being created as a Proc; work-around race in Proc.sendRefresh.
    
    frysk-core/frysk/proc/live/ChangeLog
    2008-03-18  Andrew Cagney  <cagney@redhat.com>
    
        * TestTaskObserverBlocked.java (BlockedFibonacci): Register the
        process with StopEventLoopWhenProcTerminated earlier.
        * LinuxPtraceProc.java: Add more logging.
        * LinuxPtraceHost.java (requestProc(int,FindProc)): Refresh the
        proc, not its tasks.
    
    frysk-sys/frysk/sys/proc/ChangeLog
    2008-03-18  Andrew Cagney  <cagney@redhat.com>
    
        * ProcBuilder.java: Use ProcessIdentifier.intValue() not
        .hashCode().