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


Date: Thu, 04 Apr 2013 12:42:21 -0500
From: David Smith <dsmith@xxxxxxxxxx>
Subject: Re: [DynInst_API:] oneTimeCode() and exit callbacks
On 04/04/2013 10:40 AM, Andrew Bernat wrote:
> On Apr 4, 2013, at 8:36 AM, David Smith <dsmith@xxxxxxxxxx
> <mailto:dsmith@xxxxxxxxxx>> wrote:
> 
>> Yes, I believe that output is from the correct point in the program's
>> execution.
> 
> Then it's an excellent question as to what we actually executed. 
> 
> ... argh, this isn't controlled by an environment flag. It should be. 
> 
> Can you edit dyninstAPI/src/dynProcess.C, line 2127 (should be // DEBUG)
> and remove the #if 0 /#endif pair? Then set DYNINST_DEBUG_SIGNAL as well
> as DYNINST_DEBUG_PROCCONTROL and send me the output? That will print a
> disassembly of the RPC so that I can check it. 

Here's what I get after enabling that debug code (with
DYNINST_DEBUG_SIGNAL/DYNINST_DEBUG_PROCCONTROL on):

====
[140737318881344]BPatch_process.C[943]: UI top of oneTimeCode...
	3080000750: nop
	3080000751: nop
	3080000752: nop
	3080000753: nop
	3080000754: nop
	3080000755: nop
	3080000756: nop
	3080000757: nop
	3080000758: lea RSP, ESP + ffffff50
	3080000760: mov [ESP + 20], RAX
	3080000765: lahf
	3080000766: seto AL
	3080000769: mov [ESP + 28], RAX
	308000076e: lea RAX, ESP + b0
	3080000776: and RSP, e0
	308000077a: mov [ESP], RAX
	308000077e: mov RAX, [RAX + ffffff78]
	3080000785: add AL, 7f
	3080000788: sahf
	3080000789: mov RAX, [ESP]
	308000078d: mov RAX, [RAX + ffffff70]
	3080000794: push RAX, RSP
	3080000795: push RBX, RSP
	3080000796: push R10, RSP
	3080000798: push R11, RSP
	308000079a: push R12, RSP
	308000079c: push R13, RSP
	308000079e: push R14, RSP
	30800007a0: push R15, RSP
	30800007a2: push R8, RSP
	30800007a4: push R9, RSP
	30800007a6: push RCX, RSP
	30800007a7: push RDX, RSP
	30800007a8: push RSI, RSP
	30800007a9: push RDI, RSP
	30800007aa: lahf
	30800007ab: seto AL
	30800007ae: push RAX, RSP
	30800007af: push RBP, RSP
	30800007b0: mov RBP, RSP
	30800007b3: lea RSP, ESP + fffffe00
	30800007bb: fxsave [ESP]
	30800007bf: push RSP, RSP
	30800007c0: lea RSP, ESP + ffffffffffffffe8
	30800007c5: mov RSI, 0
	30800007cf: mov RDI, 0
	30800007d9: mov RAX, 0
	30800007e3: mov RBX, f6b42210
	30800007ed: call RBX
	30800007ef: lea RSP, ESP + 18
	30800007f4: pop RSP, RSP
	30800007f5: int 3
	30800007f6: int 3
[140737318881344]dynProcess.C[2169]: Launching IRPC
[../src/process.C:6596-U] - Running SYNC RPC
[../src/irpc.C:321-U] - Posting iRPC 4 to process 1371, selecting a
thread...
[../src/irpc.C:359-U] - Thread 1371 has 0 running/posted iRPCs
[../src/irpc.C:367-U] - Selected thread 1371 for iRPC 4
[../src/irpc.C:376-U] - Posting iRPC 4 to thread 1371
[../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 1371:
	U-4(167),
[../src/process.C:4424-U] - Changing user state for 1371/1371 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 1371
[../src/process.C:3344-U] - 1371/1371: setting target state to Running
[../src/process.C:3562-U] - Checking thread 1371/1371 for events thrown
before continue
[../src/process.C:3570-U] - Found thread 1371/1371 ready to run IRPC,
not continuing
[../src/process.C:4296-U] - Desyncing 1371/1371 irpc setup state to level 1
[../src/process.C:4424-U] - Changing irpc setup state for 1371/1371 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 1371 are ready
[../src/process.C:3344-U] - 1371/1371: setting target state to Stopped
[../src/process.C:827-U] - Current Threading State for 1371:
[../src/process.C:843-U] - 1371/1371 hand: stopped, gen: stopped, irpc
setup: stopped, code: ----S----------RSS
[../src/process.C:852-U] - Running plat_syncRunState on 1371
[../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 1371/1371 of
type User in state Prepping
[../src/irpc.C:1210-U] - Marking RPC 4 on 1371/1371 as prepped
[../src/irpc.C:1220-U] - Saving RPC state on 1371/1371
[../src/irpc.C:710-U] - Saving state for iRPC 4
[../src/irpc.C:728-U] - Saving original application registers for 1371/1371
[../src/process.C:3681-U] - Reading registers for thread 1371
[../src/process.C:3695-U] - plat_getAllRegisters on 1371/1371
[../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 55b, 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 55b, 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 1371
[../src/irpc.C:739-U] - Saving original 167 bytes of memory at
3080000750 from application for 1371/1371
[../src/process.C:1321-U] - Reading from remote memory 3080000750 to
0x5b932c0, size = 167 on 1371/1371
[../src/irpc.C:1245-U] - Writing RPC on 1371
[../src/irpc.C:770-U] - Writing rpc 4 memory to 3080000750->30800007f7
[../src/process.C:1378-U] - Writing to remote memory 3080000750 from
0x5b91bb0, size = 167 on 1371/1371
[../src/irpc.C:788-U] - IRPC: Setting 1371/1371 PC to 3080000758
[../src/process.C:3889-U] - 1371/1371: Setting x86_64::rip to
0x3080000758...
[../src/process.C:3914-U] - Setting register x86_64::rip for thread 1371
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 1371/1371 to running
[../src/process.C:4321-U] - Restoring 1371/1371 irpc setup state to level 0
[../src/process.C:4424-U] - Changing irpc setup state for 1371/1371 from
stopped to dontcare
[../src/process.C:778-U] - At top of syncRunState for 1371
[../src/process.C:3344-U] - 1371/1371: setting target state to Running
[../src/process.C:3562-U] - Checking thread 1371/1371 for events thrown
before continue
[../src/process.C:815-U] - Checking if any ProcStop events on 1371 are ready
[../src/process.C:3344-U] - 1371/1371: setting target state to Running
[../src/process.C:827-U] - Current Threading State for 1371:
[../src/process.C:843-U] - 1371/1371 hand: stopped, gen: stopped, user:
running, code: ---------------RSS
[../src/process.C:852-U] - Running plat_syncRunState on 1371
[../src/process.C:3009-U] - intCont on thread 1371/1371
[../src/linux.C:1134-U] - Continuing thread 1371
[../src/linux.C:1184-U] - Calling PTRACE_CONT on 1371 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 1371/1371 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 1371/1371 from
stopped to running
[../src/process.C:5830-U] - Clearing register pool for 1371/1371
[../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 1371:
[../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 1371/1371
[../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] - 1371/1371 trap at 30800007f5 lies between
3080000750 and 30800007f7, is iRPC 4 trap
[../src/linux.C:397-G] - Decoded event to rpc completion on 1371/1371 at
30800007f5
[../src/generator.C:143-G] - Setting generator state to statesync
[../src/process.C:2130-G] - Event RPC is thread synchronous, marking
thread 1371 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 1371/1371 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 1371 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 1371/1371 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 1371/1371 from
running to stopped
[../src/handler.C:437-U] - Handling event 'RPC' with handler 'Callback'
[../src/handler.C:2161-U] - Changing callback state of 1371 before CB
[../src/process.C:4296-U] - Desyncing 1371/1371 callback state to level 1
[../src/process.C:4424-U] - Changing callback state for 1371/1371 from
dontcare to ditto
[../src/process.C:4354-U] - Leaving user state for 1371/1371 in state
stopped
[../src/handler.C:2184-U] - Triggering callback for event 'RPC'
[../src/handler.C:2189-U] - Triggering callback #0 for event 'RPC'
[140737318881344]pcEventMuxer.C[364]: Begin callbackMux, process pointer
= 0x6c3070, event RPC
[../src/process.C:3795-U] - Get register value for thread 1371, 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 1371
[../src/response.C:286-U] - Waiting for async event 375, complete
[140737318881344]pcEventMuxer.C[390]: iRPC 4 return value = 0x0
[140737318881344]pcEventMuxer.C[439]: Added event RPC to mailbox, size now 1
[140737318881344]pcEventMuxer.C[394]: after muxing event, mailbox size is 1
[../src/handler.C:2200-U] - Callback #0 return cbProcStop/cbProcStop
[../src/process.C:4354-U] - Leaving user state for 1371/1371 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 1371/1371 in state
stopped
[../src/handler.C:2223-U] - Handling return value for child process/thread
[../src/handler.C:2243-U] - Restoring callback state of 1371/1371 after CB
[../src/process.C:4321-U] - Restoring 1371/1371 callback state to level 0
[../src/process.C:4424-U] - Changing callback state for 1371/1371 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 1371/1371
[../src/irpc.C:1044-U] - Restoring memory to 3080000750 from 0x5b932c0
of size 167
[../src/process.C:1378-U] - Writing to remote memory 3080000750 from
0x5b932c0, size = 167 on 1371/1371
[../src/irpc.C:1086-U] - Restoring all registers
[../src/process.C:3750-U] - Setting registers for thread 1371
[../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 55b, 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 55b, 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 1371
[../src/process.C:3767-U] - Successfully set all registers for 1371
[../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 1371
[../src/process.C:3344-U] - 1371/1371: setting target state to Stopped
[../src/process.C:815-U] - Checking if any ProcStop events on 1371 are ready
[../src/process.C:3344-U] - 1371/1371: setting target state to Stopped
[../src/process.C:827-U] - Current Threading State for 1371:
[../src/process.C:843-U] - 1371/1371 hand: stopped, gen: stopped, user:
stopped, code: ---------------SSS
[../src/process.C:852-U] - Running plat_syncRunState on 1371
[../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
[140737318881344][pcEventMuxer.C/83]: PCEventMuxer waiting for events,
non-blocking
[../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
[140737318881344][pcEventMuxer.C:86] after PC event handling, 1 events
in mailbox
[140737318881344]pcEventMuxer.C[464]: Returning event RPC from mailbox
[140737318881344]pcEventHandler.C[65]: attempting to handle event RPC on
thread 1371/1371
[140737318881344]pcEventHandler.C[957]: handling completion of RPC 4 on
thread 1371/1371
[140737318881344]pcEventHandler.C[962]: delivering callbacks for RPC 4
[140737318881344]pcEventHandler.C[969]: continue requested after RPC 4
[140737318881344]dynProcess.C[3290]: removed sync rpc thread 1371/0
[140737318881344]pcEventHandler.C[194]: continue condition ( 1 1 1 1 1 1 )
[140737318881344]pcEventHandler.C[206]: user wants process running after
event handling
[140737318881344]pcEventHandler.C[214]: continuing entire process
[140737318881344]dynProcess.C[1097]: Continuing process 1371
[140737318881344]dynProcess.C[1109]: process currently in event
handling, not continuing
[140737318881344]pcEventHandler.C[242]: finished handling event: RPC
(err = false)
[140737318881344]BPatch_process.C[970]: RPC completed, process status
running
====

-- 
David Smith
dsmith@xxxxxxxxxx
Red Hat
http://www.redhat.com
256.217.0141 (direct)
256.837.0057 (fax)
[← Prev in Thread] Current Thread [Next in Thread→]