Why does an order get processed and when can I see its fill price

I noticed that my market orders are not getting filled at prices even remotely close to the (minute) bar's OHLC prices, so I tried capturing the
"filled" price by deploying the following function

def tallyResults(context,order_id, security):
order_data = get_order(order_id)
#log.info(order_data)
if order_data is None:
log.info("No order found.")
return

        if order_data['status'] == 1:  
            log.info("Order is filled.")  
            log.info('Total commission: '+str(order_data['commission']))  
            log.info('Commission per share: '+str(order_data['commission']/order_data['filled']))  
            log.info('Cost basis: '+str(context.portfolio.positions[security].cost_basis))  
        else:  
            log.info("Order isn't filled yet.")  

        log.info('-------------------------------')

I assume I cannot call that function right after I place my market orders, as they will only be filled on the next bar, so at the top of handleData
I add the following

if context.showedMarketFill == False:    #this is also initialized value  
      tallyResults(context,context.order_id,context.security)  
      context.showedMarketFill = True

When certain conditions get filled , here's how I order:

    # now we can do the transaction itself  
    if (not beShort and p >= maxs[context.security]) or (beShort and p <= mins[context.security]) :  
        if not beShort: # we want to go long  
            # order the shares at market price  
            context.order_id=order_target_percent(context.security, context.leverage)  
            # for logging purposes find out how many shares ordered  
            context.shares_traded= math.floor(context.portfolio.portfolio_value/p)  * context.leverage  
            #place a stop limit (above for longs , below for shorts)  
            context.stop = order_target_percent(context.security, 0.0, style=StopLimitOrder(context.limitPrice,context.breachpoint ) )  

            log.info('{} Breached High of  {:+.2f} , so bought {} shares @ {:+.2f}, set stop @ {:+.2f} limit {:+.2f}, set target @ {:+.2f}'.format(exchange_time,maxs[context.security],context.shares_traded,p,context.breachpoint,context.limitPrice,context.target))  
            tallyResults(context,context.order_id,context.security)  
            context.wasShort = False

My log files never provide me the "filled" price I get the following
2015-07-13handle_data:254INFO2015-07-13 12:06:00-04:00 Breached High of +125.32 , so bought 7965.0 shares @ +125.32, set stop @ +125.08 limit +124.46, set target @ +125.47
2015-07-13tallyResults:374INFOOrder isn't filled yet.
2015-07-13tallyResults:376INFO-------------------------------

The first line of the log file represents my best guess (based on current price) of what values I hope to transact at. Actual values are WAY different, which
is why I'm trying to see actual "filled" values

There must be an easier way to skin this cat. How are you guys doing it?

Thanks
Serge