Re: [DynInst_API:] oneTimeCode() and exit callbacks

[David Smith <dsmith@xxxxxxxxxx>]

On 03/26/2013 10:55 AM, Andrew Bernat wrote:
> On Mar 26, 2013, at 10:16 AM, David Smith <dsmith@xxxxxxxxxx
> <mailto:dsmith@xxxxxxxxxx>> wrote:
> 
>> Andrew,
>>
>> Have you had a chance to take a look at this?
> 
> Thanks for the reminder. It looks like we have a conflict of desires
> going on inside of Dyninst. The "isStopped" method returns true if the
> user explicitly requests the process to be stopped, but false if it
> stopped for some other reason (e.g. handling a signal). 
> 
> As a quick fix, can you just comment out the isStopped check in
> BPatch_process::oneTimeCode? The ProcControl layer will handle things
> appropriately. 

After that change, oneTimeCode)( doesn't complain, but the function that
is supposed to be called by oneTimeCode() doesn't actually get called
either.

Here's the output DYNINST_DEBUG_PROCCONTROL=1 produces when
oneTimeCode() is called.

====
[../src/process.C:6596-U] - Running SYNC RPC
[../src/irpc.C:321-U] - Posting iRPC 4 to process 29334, selecting a
thread...
[../src/irpc.C:359-U] - Thread 29334 has 0 running/posted iRPCs
[../src/irpc.C:367-U] - Selected thread 29334 for iRPC 4
[../src/irpc.C:376-U] - Posting iRPC 4 to thread 29334
[../src/process.C:8387-U] - Adjusting counter SyncRPCs by 1, before 0,
after 1
[../src/irpc.C:431-U] - RPC 4 already has allocated memory, added to end
[../src/irpc.C:496-U] - Posted iRPC list for 29334:
	U-4(167),
[../src/process.C:4424-U] - Changing user state for 29334/29334 from
stopped to running
[../src/mailbox.C:120-U] - Added event Nop to mailbox, size = 1 + 0 + 0 = 1
[../src/process.C:952-U] - Top of waitAndHandleEvents.  Block = true
[../src/process.C:1001-U] - Polling for events = !F && ((T && !F && F)
|| F || F || F || F || F || F || F)
[../src/mailbox.C:171-U] - Returning event Nop from mailbox
[../src/handler.C:402-U] - Event Nop added to handle list with handler
Nop Handler
[../src/handler.C:419-U] - Have event Nop on Nop Handler
[../src/handler.C:437-U] - Handling event 'Nop' with handler 'Nop Handler'
[../src/process.C:778-U] - At top of syncRunState for 29334
[../src/process.C:3344-U] - 29334/29334: setting target state to Running
[../src/process.C:3562-U] - Checking thread 29334/29334 for events
thrown before continue
[../src/process.C:3570-U] - Found thread 29334/29334 ready to run IRPC,
not continuing
[../src/process.C:4296-U] - Desyncing 29334/29334 irpc setup state to
level 1
[../src/process.C:4424-U] - Changing irpc setup state for 29334/29334
from dontcare to stopped
[../src/event.C:132-U] - Setting callback suppress for RPCLaunch
[../src/mailbox.C:120-U] - Added event RPCLaunch to mailbox, size = 1 +
0 + 0 = 1
[../src/process.C:815-U] - Checking if any ProcStop events on 29334 are
ready
[../src/process.C:3344-U] - 29334/29334: setting target state to Stopped
[../src/process.C:827-U] - Current Threading State for 29334:
[../src/process.C:843-U] - 29334/29334 hand: stopped, gen: stopped, irpc
setup: stopped, code: ----S----------RSS
[../src/process.C:852-U] - Running plat_syncRunState on 29334
[../src/process.C:1001-U] - Polling for events = !F && ((T && !T && ?)
|| F || F || F || F || F || F || F)
[../src/mailbox.C:171-U] - Returning event RPCLaunch from mailbox
[../src/handler.C:402-U] - Event RPCLaunch added to handle list with
handler iRPC Launch Handler
[../src/handler.C:419-U] - Have event RPCLaunch on iRPC Launch Handler
[../src/handler.C:437-U] - Handling event 'RPCLaunch' with handler 'iRPC
Launch Handler'
[../src/irpc.C:1202-U] - Handling next posted irpc 4 on 29334/29334 of
type User in state Prepping
[../src/irpc.C:1210-U] - Marking RPC 4 on 29334/29334 as prepped
[../src/irpc.C:1220-U] - Saving RPC state on 29334/29334
[../src/irpc.C:710-U] - Saving state for iRPC 4
[../src/irpc.C:728-U] - Saving original application registers for
29334/29334
[../src/process.C:3681-U] - Reading registers for thread 29334
[../src/process.C:3695-U] - plat_getAllRegisters on 29334/29334
[../src/linux.C:1935-U] - Register x86_64::rip has value 30f56ef679,
offset 128
[../src/linux.C:1935-U] - Register x86_64::rax has value 0, offset 80
[../src/linux.C:1935-U] - Register x86_64::rcx has value
ffffffffffffffff, offset 88
[../src/linux.C:1935-U] - Register x86_64::rdx has value 30f56ef679,
offset 96
[../src/linux.C:1935-U] - Register x86_64::rbx has value 7ffff6f7181c,
offset 40
[../src/linux.C:1935-U] - Register x86_64::rsp has value 7fffffffddd8,
offset 152
[../src/linux.C:1935-U] - Register x86_64::rbp has value 7296, offset 32
[../src/linux.C:1935-U] - Register x86_64::rsi has value 7, offset 104
[../src/linux.C:1935-U] - Register x86_64::rdi has value 7296, offset 112
[../src/linux.C:1935-U] - Register x86_64::r8 has value 7ffff6f7181c,
offset 72
[../src/linux.C:1935-U] - Register x86_64::r9 has value 7ffff6f7181c,
offset 64
[../src/linux.C:1935-U] - Register x86_64::r10 has value 30f59bbb00,
offset 56
[../src/linux.C:1935-U] - Register x86_64::r11 has value 246, offset 48
[../src/linux.C:1935-U] - Register x86_64::r12 has value 7, offset 24
[../src/linux.C:1935-U] - Register x86_64::r13 has value 0, offset 16
[../src/linux.C:1935-U] - Register x86_64::r14 has value 0, offset 8
[../src/linux.C:1935-U] - Register x86_64::r15 has value 0, offset 0
[../src/linux.C:1935-U] - Register x86_64::ds has value 0, offset 184
[../src/linux.C:1935-U] - Register x86_64::es has value 0, offset 192
[../src/linux.C:1935-U] - Register x86_64::fs has value 0, offset 200
[../src/linux.C:1935-U] - Register x86_64::gs has value 0, offset 208
[../src/linux.C:1935-U] - Register x86_64::cs has value 33, offset 136
[../src/linux.C:1935-U] - Register x86_64::ss has value 2b, offset 160
[../src/linux.C:1935-U] - Register x86_64::flags has value 246, offset 144
[../src/linux.C:1935-U] - Register x86_64::orax has value c8, offset 120
[../src/linux.C:1935-U] - Register x86_64::fsbase has value
7ffff6d46740, offset 168
[../src/linux.C:1935-U] - Register x86_64::gsbase has value 0, offset 176
[../src/linux.C:1935-U] - Register x86_64::dr0 has value 0, offset 848
[../src/linux.C:1935-U] - Register x86_64::dr1 has value 0, offset 856
[../src/linux.C:1935-U] - Register x86_64::dr2 has value 0, offset 864
[../src/linux.C:1935-U] - Register x86_64::dr3 has value 0, offset 872
[../src/linux.C:1935-U] - Register x86_64::dr4 has value 0, offset 880
[../src/linux.C:1935-U] - Register x86_64::dr5 has value 0, offset 888
[../src/linux.C:1935-U] - Register x86_64::dr6 has value 0, offset 896
[../src/linux.C:1935-U] - Register x86_64::dr7 has value 0, offset 904
[../src/process.C:3719-U] - Successfully retrieved all registers for 29334
[../src/irpc.C:739-U] - Saving original 167 bytes of memory at
3080000750 from application for 29334/29334
[../src/process.C:1321-U] - Reading from remote memory 3080000750 to
0x5bb0a60, size = 167 on 29334/29334
[../src/irpc.C:1245-U] - Writing RPC on 29334
[../src/irpc.C:770-U] - Writing rpc 4 memory to 3080000750->30800007f7
[../src/process.C:1378-U] - Writing to remote memory 3080000750 from
0x5baf470, size = 167 on 29334/29334
[../src/irpc.C:788-U] - IRPC: Setting 29334/29334 PC to 3080000758
[../src/process.C:3889-U] - 29334/29334: Setting x86_64::rip to
0x3080000758...
[../src/process.C:3914-U] - Setting register x86_64::rip for thread
29334 to 3080000758
[../src/linux.C:2194-U] - Set register x86_64::rip (size 8, offset 128)
to value 3080000758
[../src/irpc.C:817-U] - Moving next iRPC for 29334/29334 to running
[../src/process.C:4321-U] - Restoring 29334/29334 irpc setup state to
level 0
[../src/process.C:4424-U] - Changing irpc setup state for 29334/29334
from stopped to dontcare
[../src/process.C:778-U] - At top of syncRunState for 29334
[../src/process.C:3344-U] - 29334/29334: setting target state to Running
[../src/process.C:3562-U] - Checking thread 29334/29334 for events
thrown before continue
[../src/process.C:815-U] - Checking if any ProcStop events on 29334 are
ready
[../src/process.C:3344-U] - 29334/29334: setting target state to Running
[../src/process.C:827-U] - Current Threading State for 29334:
[../src/process.C:843-U] - 29334/29334 hand: stopped, gen: stopped,
user: running, code: ---------------RSS
[../src/process.C:852-U] - Running plat_syncRunState on 29334
[../src/process.C:3009-U] - intCont on thread 29334/29334
[../src/linux.C:1134-U] - Continuing thread 29334
[../src/linux.C:1184-U] - Calling PTRACE_CONT on 29334 with signal 0
[../src/process.C:8387-U] - Adjusting counter HandlerRunningThreads by
1, before 0, after 1
[../src/process.C:8387-U] - Adjusting counter SyncRPCRunningThreads by
1, before 0, after 1
[../src/process.C:4424-U] - Changing handler state for 29334/29334 from
stopped to running
[../src/process.C:8387-U] - Adjusting counter GeneratorRunningThreads by
1, before 0, after 1
[../src/process.C:4424-U] - Changing generator state for 29334/29334
from stopped to running
[../src/process.C:5830-U] - Clearing register pool for 29334/29334
[../src/memcache.C:573-U] - Clearing memCache
[../src/generator.C:277-G] - Entry to generator::hasLiveProc()
[../src/generator.C:287-G] - Generator has running threads, returning
true from hasLiveProc
[../src/generator.C:441-G] - processWait returning true
[../src/generator.C:143-G] - Setting generator state to system_blocked
[../src/generator.C:206-G] - About to getEvent()
[../src/linux.C:117-G] - blocking in waitpid
[../src/linux.C:138-G] - Waitpid return status 1407 for pid 29334:
[../src/linux.C:144-G] - Stopped with signal 5
[../src/generator.C:208-G] - Got event
[../src/generator.C:143-G] - Setting generator state to decoding
[../src/linux.C:271-G] - Decoding event for 29334/29334
[../src/linux.C:278-G] - Decoded to signal 5
[../src/linux.C:1979-G] - Register x86_64::rip has value 0x30800007f6
[../src/irpc.C:930-G] - 29334/29334 trap at 30800007f5 lies between
3080000750 and 30800007f7, is iRPC 4 trap
[../src/linux.C:397-G] - Decoded event to rpc completion on 29334/29334
at 30800007f5
[../src/generator.C:143-G] - Setting generator state to statesync
[../src/process.C:2130-G] - Event RPC is thread synchronous, marking
thread 29334 generator stopped
[../src/process.C:8387-G] - Adjusting counter GeneratorRunningThreads by
-1, before 1, after 0
[../src/process.C:4424-G] - Changing generator state for 29334/29334
from running to stopped
[../src/generator.C:143-G] - Setting generator state to queueing
[../src/mailbox.C:120-G] - Added event RPC to mailbox, size = 1 + 0 + 0 = 1
[../src/generator.C:143-G] - Setting generator state to none
[../src/generator.C:143-G] - Setting generator state to process_blocked
[../src/generator.C:428-G] - Checking for live processes
[../src/generator.C:277-G] - Entry to generator::hasLiveProc()
[../src/generator.C:307-G] - No live processes, ret false
[../src/generator.C:430-G] - Checked and found no live processes
[../src/process.C:1001-U] - Blocking for events = !F && ((T && !T && ?)
|| T || ? || ? || ? || ? || ? || ?)
[../src/mailbox.C:171-U] - Returning event RPC from mailbox
[../src/process.C:2130-U] - Event RPC is thread synchronous, marking
thread 29334 handler stopped
[../src/process.C:8387-U] - Adjusting counter HandlerRunningThreads by
-1, before 1, after 0
[../src/process.C:8387-U] - Adjusting counter SyncRPCRunningThreads by
-1, before 1, after 0
[../src/process.C:4424-U] - Changing handler state for 29334/29334 from
running to stopped
[../src/handler.C:402-U] - Event RPC added to handle list with handler
iRPC PreCallback Handler
[../src/handler.C:402-U] - Event RPC added to handle list with handler
Callback
[../src/handler.C:402-U] - Event RPC added to handle list with handler
RPC Handler
[../src/handler.C:419-U] - Have event RPC on iRPC PreCallback Handler
[../src/handler.C:419-U] - Have event RPC on Callback
[../src/handler.C:419-U] - Have event RPC on RPC Handler
[../src/handler.C:437-U] - Handling event 'RPC' with handler 'iRPC
PreCallback Handler'
[../src/process.C:4424-U] - Changing user state for 29334/29334 from
running to stopped
[../src/handler.C:437-U] - Handling event 'RPC' with handler 'Callback'
[../src/handler.C:2161-U] - Changing callback state of 29334 before CB
[../src/process.C:4296-U] - Desyncing 29334/29334 callback state to level 1
[../src/process.C:4424-U] - Changing callback state for 29334/29334 from
dontcare to ditto
[../src/process.C:4354-U] - Leaving user state for 29334/29334 in state
stopped
[../src/handler.C:2184-U] - Triggering callback for event 'RPC'
[../src/handler.C:2189-U] - Triggering callback #0 for event 'RPC'
[../src/process.C:3795-U] - Get register value for thread 29334,
register x86_64::rax
[../src/linux.C:1979-U] - Register x86_64::rax has value 0x0
[../src/process.C:3867-U] - Returning register value 0 for register
x86_64::rax on 29334
[../src/response.C:286-U] - Waiting for async event 375, complete
[../src/handler.C:2200-U] - Callback #0 return cbProcStop/cbProcStop
[../src/process.C:4354-U] - Leaving user state for 29334/29334 in state
stopped
[../src/handler.C:2218-U] - Handling return value for main process
[../src/handler.C:2143-U] - Callbacks returned process stop
[../src/process.C:4354-U] - Leaving user state for 29334/29334 in state
stopped
[../src/handler.C:2223-U] - Handling return value for child process/thread
[../src/handler.C:2243-U] - Restoring callback state of 29334/29334 after CB
[../src/process.C:4321-U] - Restoring 29334/29334 callback state to level 0
[../src/process.C:4424-U] - Changing callback state for 29334/29334 from
ditto to dontcare
[../src/handler.C:437-U] - Handling event 'RPC' with handler 'RPC Handler'
[../src/irpc.C:1028-U] - Handling RPC 4 completion on 29334/29334
[../src/irpc.C:1044-U] - Restoring memory to 3080000750 from 0x5bb0a60
of size 167
[../src/process.C:1378-U] - Writing to remote memory 3080000750 from
0x5bb0a60, size = 167 on 29334/29334
[../src/irpc.C:1086-U] - Restoring all registers
[../src/process.C:3750-U] - Setting registers for thread 29334
[../src/linux.C:2142-U] - Register x86_64::rip gets value 30f56ef679,
offset 128
[../src/linux.C:2142-U] - Register x86_64::rax gets value 0, offset 80
[../src/linux.C:2142-U] - Register x86_64::rcx gets value
ffffffffffffffff, offset 88
[../src/linux.C:2142-U] - Register x86_64::rdx gets value 30f56ef679,
offset 96
[../src/linux.C:2142-U] - Register x86_64::rbx gets value 7ffff6f7181c,
offset 40
[../src/linux.C:2142-U] - Register x86_64::rsp gets value 7fffffffddd8,
offset 152
[../src/linux.C:2142-U] - Register x86_64::rbp gets value 7296, offset 32
[../src/linux.C:2142-U] - Register x86_64::rsi gets value 7, offset 104
[../src/linux.C:2142-U] - Register x86_64::rdi gets value 7296, offset 112
[../src/linux.C:2142-U] - Register x86_64::r8 gets value 7ffff6f7181c,
offset 72
[../src/linux.C:2142-U] - Register x86_64::r9 gets value 7ffff6f7181c,
offset 64
[../src/linux.C:2142-U] - Register x86_64::r10 gets value 30f59bbb00,
offset 56
[../src/linux.C:2142-U] - Register x86_64::r11 gets value 246, offset 48
[../src/linux.C:2142-U] - Register x86_64::r12 gets value 7, offset 24
[../src/linux.C:2142-U] - Register x86_64::r13 gets value 0, offset 16
[../src/linux.C:2142-U] - Register x86_64::r14 gets value 0, offset 8
[../src/linux.C:2142-U] - Register x86_64::r15 gets value 0, offset 0
[../src/linux.C:2142-U] - Register x86_64::ds gets value 0, offset 184
[../src/linux.C:2142-U] - Register x86_64::es gets value 0, offset 192
[../src/linux.C:2142-U] - Register x86_64::fs gets value 0, offset 200
[../src/linux.C:2142-U] - Register x86_64::gs gets value 0, offset 208
[../src/linux.C:2142-U] - Register x86_64::cs gets value 33, offset 136
[../src/linux.C:2142-U] - Register x86_64::ss gets value 2b, offset 160
[../src/linux.C:2142-U] - Register x86_64::flags gets value 246, offset 144
[../src/linux.C:2142-U] - Register x86_64::orax gets value c8, offset 120
[../src/linux.C:2142-U] - Register x86_64::fsbase gets value
7ffff6d46740, offset 168
[../src/linux.C:2142-U] - Register x86_64::gsbase gets value 0, offset 176
[../src/linux.C:2070-U] - Successfully set the values of all registers
for 29334
[../src/process.C:3767-U] - Successfully set all registers for 29334
[../src/irpc.C:1126-U] - RPC 4 is moving to state finished
[../src/process.C:8387-U] - Adjusting counter SyncRPCs by -1, before 1,
after 0
[../src/process.C:778-U] - At top of syncRunState for 29334
[../src/process.C:3344-U] - 29334/29334: setting target state to Stopped
[../src/process.C:815-U] - Checking if any ProcStop events on 29334 are
ready
[../src/process.C:3344-U] - 29334/29334: setting target state to Stopped
[../src/process.C:827-U] - Current Threading State for 29334:
[../src/process.C:843-U] - 29334/29334 hand: stopped, gen: stopped,
user: stopped, code: ---------------SSS
[../src/process.C:852-U] - Running plat_syncRunState on 29334
[../src/process.C:1001-U] - Polling for events = !F && ((T && !T && ?)
|| F || F || F || F || F || F || F)
[../src/mailbox.C:149-U] - Polled mailbox for messages, but none found
[../src/process.C:1020-U] - Returning after handling events
[../src/process.C:1126-U] - Leaving WaitAndHandleEvents with return
true, 'cause we're done
[../src/process.C:8628-H] - Handler starting to check for events
[../src/process.C:8636-H] - Events already handled, going back to sleep
[../src/process.C:8628-H] - Handler starting to check for events
[../src/process.C:8636-H] - Events already handled, going back to sleep
[../src/process.C:6124-U] - User triggered event handling
[../src/process.C:952-U] - Top of waitAndHandleEvents.  Block = false
[../src/process.C:1001-U] - Polling for events = !F && ((F && !? && ?)
|| F || F || F || F || F || F || F)
[../src/mailbox.C:149-U] - Polled mailbox for messages, but none found
[../src/process.C:1041-U] - Poll failed to find events
[../src/process.C:1126-U] - Leaving WaitAndHandleEvents with return
false, 'cause we're done
[../src/process.C:6134-U] - Polling Process::handleEvents returning
false due to no events
====

-- 
David Smith
dsmith@xxxxxxxxxx
Red Hat
http://www.redhat.com
256.217.0141 (direct)
256.837.0057 (fax)