Handle exceptions correctly if native function throws exception

src/ext/MemoryTracker.c

@@ -66,9 +66,7 @@ typedef struct EmbeddedTrackingDataHeader EmbeddedTrackingDataHeader;
 struct DeserializedTrackingData
 {
     EmbeddedTrackingDataHeader* embedded;
-
     void* stackTraceAddresses[ maxCaptureStackTraceDepth ];
-
     UInt32 suffixMagic;
 };
 typedef struct DeserializedTrackingData DeserializedTrackingData;
@@ -83,8 +81,9 @@ void constructMemoryTracker( MemoryTracker* memTracker )
     memTracker->level = memoryTrackingLevel_all;
     memTracker->abortOnMemoryLeak = ELASTIC_APM_MEMORY_TRACKING_DEFAULT_ABORT_ON_MEMORY_LEAK;
     memTracker->allocatedPersistent = 0;
+    initIntrusiveDoublyLinkedList( &memTracker->allocatedPersistentBlocks );
     memTracker->allocatedRequestScoped = 0;
-    initIntrusiveDoublyLinkedList( &memTracker->allocatedBlocks );
+    initIntrusiveDoublyLinkedList( &memTracker->allocatedRequestScopedBlocks );
 
     ELASTIC_APM_ASSERT_VALID_MEMORY_TRACKER( memTracker );
 }
@@ -138,6 +137,7 @@ void addToTrackedAllocatedBlocks(
         MemoryTracker* memTracker,
         const void* allocatedBlock,
         size_t originallyRequestedSize,
+        bool isPersistent,
         StringView filePath,
         UInt lineNumber,
         bool isString,
@@ -146,8 +146,11 @@ void addToTrackedAllocatedBlocks(
 {
     EmbeddedTrackingDataHeader* trackingDataHeader = allocatedBlockToTrackingData( allocatedBlock, originallyRequestedSize );
     ELASTIC_APM_ZERO_STRUCT( trackingDataHeader );
+    UInt64* allocated = isPersistent ? &memTracker->allocatedPersistent : &memTracker->allocatedRequestScoped;
+    IntrusiveDoublyLinkedList* allocatedBlocks = isPersistent ? &memTracker->allocatedPersistentBlocks : &memTracker->allocatedRequestScopedBlocks;
 
-    addToIntrusiveDoublyLinkedListBack( &memTracker->allocatedBlocks, &trackingDataHeader->intrusiveNode );
+    *allocated += originallyRequestedSize;
+    addToIntrusiveDoublyLinkedListBack( allocatedBlocks, &trackingDataHeader->intrusiveNode );
 
     trackingDataHeader->prefixMagic = prefixMagicExpectedValue;
     trackingDataHeader->fileName = extractLastPartOfFilePathStringView( filePath ).begin;
@@ -182,19 +185,19 @@ void memoryTrackerAfterAlloc(
     ELASTIC_APM_ASSERT_GE_UINT64( actuallyRequestedSize, originallyRequestedSize );
     ELASTIC_APM_ASSERT_LE_UINT64( stackTraceAddressesCount, maxCaptureStackTraceDepth );
 
-    UInt64* allocated = isPersistent ? &memTracker->allocatedPersistent : &memTracker->allocatedRequestScoped;
-    *allocated += originallyRequestedSize;
-
     if ( actuallyRequestedSize > originallyRequestedSize )
+    {
         addToTrackedAllocatedBlocks(
                 memTracker,
                 allocatedBlock,
                 originallyRequestedSize,
+                isPersistent,
                 filePath,
                 lineNumber,
                 isString,
                 stackTraceAddresses,
                 stackTraceAddressesCount );
+    }
 
     ELASTIC_APM_ASSERT_VALID_MEMORY_TRACKER( memTracker );
 }
@@ -226,6 +229,7 @@ void removeFromTrackedAllocatedBlocks(
         MemoryTracker* memTracker,
         const void* allocatedBlock,
         size_t originallyRequestedSize,
+        IntrusiveDoublyLinkedList* allocatedBlocks,
         size_t* possibleActuallyRequestedSize )
 {
     EmbeddedTrackingDataHeader* trackingDataHeader = allocatedBlockToTrackingData( allocatedBlock, originallyRequestedSize );
@@ -242,7 +246,7 @@ void removeFromTrackedAllocatedBlocks(
             memoryTrackerCalcSizeToAlloc(memTracker, originallyRequestedSize, trackingDataHeader->stackTraceAddressesCount );
 
     removeCurrentNodeIntrusiveDoublyLinkedList(
-            nodeToIntrusiveDoublyLinkedListIterator( &memTracker->allocatedBlocks, &trackingDataHeader->intrusiveNode ) );
+            nodeToIntrusiveDoublyLinkedListIterator( allocatedBlocks, &trackingDataHeader->intrusiveNode ) );
 
     trackingDataHeader->prefixMagic = invalidMagicValue;
     memcpy( postHeader, &invalidMagicValue, ELASTIC_APM_FIELD_SIZEOF( DeserializedTrackingData, suffixMagic ) );
@@ -259,6 +263,7 @@ void memoryTrackerBeforeFree(
     ELASTIC_APM_ASSERT_VALID_PTR( possibleActuallyRequestedSize );
 
     UInt64* allocated = isPersistent ? &memTracker->allocatedPersistent : &memTracker->allocatedRequestScoped;
+    IntrusiveDoublyLinkedList* allocatedBlocks = isPersistent ? &memTracker->allocatedPersistentBlocks : &memTracker->allocatedRequestScopedBlocks;
 
     ELASTIC_APM_ASSERT( *allocated >= originallyRequestedSize
             , "Attempting to free more %s memory than allocated. Allocated: %"PRIu64". Attempting to free: %"PRIu64
@@ -269,7 +274,7 @@ void memoryTrackerBeforeFree(
     // if the current level (i.e., at the moment of call to free()) includes tracking for each allocation
     // then the level at the moment of call to malloc() included tracking for each allocation as well
     if ( memTracker->level >= memoryTrackingLevel_eachAllocation )
-        removeFromTrackedAllocatedBlocks( memTracker, allocatedBlock, originallyRequestedSize, possibleActuallyRequestedSize );
+        removeFromTrackedAllocatedBlocks( memTracker, allocatedBlock, originallyRequestedSize, allocatedBlocks, possibleActuallyRequestedSize );
 
     *allocated -= originallyRequestedSize;
 }
@@ -357,10 +362,7 @@ String streamAllocCallStackTrace(
 }
 
 static
-void reportAllocation(
-        const IntrusiveDoublyLinkedListNode* intrusiveListNode,
-        size_t allocationIndex,
-        size_t numberOfAllocations )
+void reportAllocation( const IntrusiveDoublyLinkedListNode* intrusiveListNode, size_t allocationIndex, size_t numberOfAllocations )
 {
     const EmbeddedTrackingDataHeader* trackingDataHeader = fromIntrusiveNodeToTrackingData( intrusiveListNode );
 
@@ -387,17 +389,21 @@ void ELASTIC_APM_ON_MEMORY_LEAK_CUSTOM_FUNC();
 static
 void verifyBalanceIsZero( const MemoryTracker* memTracker, String whenDesc, UInt64 allocated, bool isPersistent )
 {
-    if ( allocated == 0 ) return;
+    if ( allocated == 0 )
+    {
+        return;
+    }
 
-    const size_t numberOfAllocations = calcIntrusiveDoublyLinkedListSize( &memTracker->allocatedBlocks );
+    const IntrusiveDoublyLinkedList* allocatedBlocks = isPersistent ? &memTracker->allocatedPersistentBlocks : &memTracker->allocatedRequestScopedBlocks;
+    const size_t numberOfAllocations = calcIntrusiveDoublyLinkedListSize( allocatedBlocks );
     const size_t numberOfAllocationsToReport = ELASTIC_APM_MIN( numberOfAllocations, maxNumberOfLeakedAllocationsToReport );
     const IntrusiveDoublyLinkedListNode* allocationsToReport[ maxNumberOfLeakedAllocationsToReport ];
 
     // Copy allocation nodes we are going to report
     // because the code below might do more allocations
     {
         size_t allocationIndex = 0;
-        ELASTIC_APM_FOR_EACH_IN_INTRUSIVE_LINKED_LIST( allocationsIt, &memTracker->allocatedBlocks )
+        ELASTIC_APM_FOR_EACH_IN_INTRUSIVE_LINKED_LIST( allocationsIt, allocatedBlocks )
         {
             allocationsToReport[ allocationIndex++ ] = currentNodeIntrusiveDoublyLinkedList( allocationsIt );
             if ( allocationIndex == numberOfAllocationsToReport ) break;
@@ -417,7 +423,11 @@ void verifyBalanceIsZero( const MemoryTracker* memTracker, String whenDesc, UInt
     #ifdef ELASTIC_APM_ON_MEMORY_LEAK_CUSTOM_FUNC
     ELASTIC_APM_ON_MEMORY_LEAK_CUSTOM_FUNC();
     #else
-    if ( memTracker->abortOnMemoryLeak ) elasticApmAbort();
+    if ( memTracker->abortOnMemoryLeak )
+    {
+        ELASTIC_APM_FORCE_LOG_CRITICAL("Aborting on memory leak...");
+        elasticApmAbort();
+    }
     #endif
 }
 

src/ext/MemoryTracker.h

@@ -81,8 +81,9 @@ struct MemoryTracker
     bool abortOnMemoryLeak;
 
     UInt64 allocatedPersistent;
+    IntrusiveDoublyLinkedList allocatedPersistentBlocks;
     UInt64 allocatedRequestScoped;
-    IntrusiveDoublyLinkedList allocatedBlocks;
+    IntrusiveDoublyLinkedList allocatedRequestScopedBlocks;
 };
 typedef struct MemoryTracker MemoryTracker;
 
@@ -91,9 +92,9 @@ void assertValidMemoryTracker( MemoryTracker* memTracker )
 {
     ELASTIC_APM_ASSERT_VALID_PTR( memTracker );
     ELASTIC_APM_ASSERT_VALID_MEMORY_TRACKING_LEVEL( memTracker->level );
-    ELASTIC_APM_ASSERT_VALID_INTRUSIVE_LINKED_LIST( &memTracker->allocatedBlocks );
+    ELASTIC_APM_ASSERT_VALID_INTRUSIVE_LINKED_LIST( &memTracker->allocatedPersistentBlocks );
+    ELASTIC_APM_ASSERT_VALID_INTRUSIVE_LINKED_LIST( &memTracker->allocatedRequestScopedBlocks );
 }
-ELASTIC_APM_SUPPRESS_UNUSED( assertValidMemoryTracker );
 
 #define ELASTIC_APM_ASSERT_VALID_MEMORY_TRACKER( memTracker ) \
     ELASTIC_APM_ASSERT_VALID_OBJ( assertValidMemoryTracker( memTracker ) ) \

src/ext/elastic_apm_API.c

@@ -94,42 +94,121 @@ static CallToInterceptData g_functionsToInterceptData[maxFunctionsToIntercept];
 
 static uint32_t g_interceptedCallInProgressRegistrationId = 0;
 
+static
+String buildFuncDescForInterceptRegistrationId( uint32_t interceptRegistrationId, TextOutputStream* txtOutStream )
+{
+    ELASTIC_APM_ASSERT(interceptRegistrationId < g_nextFreeFunctionToInterceptId,
+                       "interceptRegistrationId: %u, g_nextFreeFunctionToInterceptId: %u"
+                       , (unsigned)interceptRegistrationId, (unsigned)g_nextFreeFunctionToInterceptId );
+
+    zend_function* funcEntry = g_functionsToInterceptData[ interceptRegistrationId ].funcEntry;
+    ELASTIC_APM_ASSERT(funcEntry != NULL, "interceptRegistrationId: %u", (unsigned)interceptRegistrationId);
+
+    String funcName = ZSTR_VAL(funcEntry->internal_function.function_name);
+    zend_class_entry* classEntry = funcEntry->internal_function.scope;
+    String className = classEntry == NULL ? NULL : ZSTR_VAL(classEntry->name);
+    bool isStatic = (funcEntry->internal_function.fn_flags & ZEND_ACC_STATIC) != 0;
+
+    return className == NULL ? funcName : streamPrintf(txtOutStream, "%s%s%s", className, isStatic ? "::" : "->", funcName);
+}
+
+static
+String findReasonCannotCallPhpCode()
+{
+    if (!EG(active))
+    {
+        return "!EG(active)";
+    }
+
+    if (EG(exception) != NULL)
+    {
+        return "EG(exception)";
+    }
+
+    return NULL;
+}
+
+static
+String buildFuncExitDesc(zval* return_value, zend_object* exception, TextOutputStream* txtOutStream)
+{
+    if (exception == NULL)
+    {
+        return streamPrintf(txtOutStream, "exited with return value of type %s (%u)", zend_get_type_by_const(Z_TYPE_P(return_value)), Z_TYPE_P(return_value));
+    }
+
+    if ((exception->ce == NULL) || (exception->ce->name == NULL))
+    {
+        return streamPrintf(txtOutStream, "thrown object of unknown type");
+    }
+
+    return streamPrintf(txtOutStream, "thrown object of type %s", ZSTR_VAL(exception->ce->name));
+}
+
 static
 void internalFunctionCallInterceptingImpl( uint32_t interceptRegistrationId, zend_execute_data* execute_data, zval* return_value )
 {
     ResultCode resultCode;
+    bool shouldCallPostHook;
+    char txtOutStreamBuf[ ELASTIC_APM_TEXT_OUTPUT_STREAM_ON_STACK_BUFFER_SIZE ];
+    TextOutputStream txtOutStream = ELASTIC_APM_TEXT_OUTPUT_STREAM_FROM_STATIC_BUFFER( txtOutStreamBuf );
+    String funcDesc = buildFuncDescForInterceptRegistrationId( interceptRegistrationId, &txtOutStream );
 
     // We SHOULD NOT log before resetting state if forked because logging might be using thread synchronization
     // which might deadlock in forked child
     ELASTIC_APM_CALL_IF_FAILED_GOTO( elasticApmEnterAgentCode( __FILE__, __LINE__, __FUNCTION__ ) );
 
-    ELASTIC_APM_LOG_TRACE_FUNCTION_ENTRY_MSG( "interceptRegistrationId: %u", interceptRegistrationId );
-
-    bool shouldCallPostHook;
+    ELASTIC_APM_LOG_TRACE_FUNCTION_ENTRY_MSG( "interceptRegistrationId: %u, funcDesc: %s", interceptRegistrationId, funcDesc );
 
     if ( g_interceptedCallInProgressRegistrationId != 0 )
     {
-        ELASTIC_APM_LOG_TRACE_FUNCTION_ENTRY_MSG(
-                "There's already an intercepted call in progress with interceptRegistrationId: %u."
-                "Nesting intercepted calls is not supported yet so invoking the original handler directly..."
-                , g_interceptedCallInProgressRegistrationId );
-        g_functionsToInterceptData[ interceptRegistrationId ].originalHandler( execute_data, return_value );
+        String inProgressFuncDesc = buildFuncDescForInterceptRegistrationId( g_interceptedCallInProgressRegistrationId, &txtOutStream );
+        ELASTIC_APM_LOG_TRACE(
+                "There's already an intercepted call in progress with interceptRegistrationId: %u (%s)."
+                " New call interceptRegistrationId: %u (%s)."
+                " Nesting intercepted calls is not supported yet so invoking the original handler directly..."
+                , g_interceptedCallInProgressRegistrationId, inProgressFuncDesc
+                , interceptRegistrationId, funcDesc );
+        g_functionsToInterceptData[ interceptRegistrationId ].originalHandler( execute_data, /* out */ return_value );
         return;
     }
 
     g_interceptedCallInProgressRegistrationId = interceptRegistrationId;
 
     shouldCallPostHook = tracerPhpPartInterceptedCallPreHook( interceptRegistrationId, execute_data );
-    g_functionsToInterceptData[ interceptRegistrationId ].originalHandler( execute_data, return_value );
+    g_functionsToInterceptData[ interceptRegistrationId ].originalHandler( execute_data, /* out */ return_value );
+    ELASTIC_APM_LOG_TRACE(
+            "Call to the original handler exited"
+            "; %s"
+            "; interceptRegistrationId: %u (%s)"
+            , buildFuncExitDesc(return_value, EG(exception), &txtOutStream)
+            , interceptRegistrationId, funcDesc );
     if ( shouldCallPostHook ) {
-        tracerPhpPartInterceptedCallPostHook( interceptRegistrationId, return_value );
+        String reasonCannotCallPhpCode = findReasonCannotCallPhpCode();
+        if (reasonCannotCallPhpCode == NULL)
+        {
+            resultCode = tracerPhpPartInterceptedCallPostHook( return_value );
+            if (resultCode != resultSuccess)
+            {
+                ELASTIC_APM_LOG_ERROR( "Post-hook call failed"
+                                       "; interceptRegistrationId: %u, funcDesc: %s, resultCode: %s (%d)"
+                                       , interceptRegistrationId, funcDesc
+                                       , resultCodeToString( resultCode ), resultCode );
+            }
+        }
+        else
+        {
+            ELASTIC_APM_LOG_DEBUG( "Post-hook cannot be called"
+                                   "; reasonCannotCallPhpCode: %s; interceptRegistrationId: %u, funcDesc: %s"
+                                   , reasonCannotCallPhpCode, interceptRegistrationId, funcDesc );
+        }
     }
 
     g_interceptedCallInProgressRegistrationId = 0;
 
-    ELASTIC_APM_LOG_TRACE_FUNCTION_EXIT_MSG( "interceptRegistrationId: %u", interceptRegistrationId );
     resultCode = resultSuccess;
     finally:
+    ELASTIC_APM_LOG_TRACE_FUNCTION_EXIT_MSG( "resultCode: %s (%d), interceptRegistrationId: %u, funcDesc: %s", resultCodeToString( resultCode ), resultCode, interceptRegistrationId, funcDesc );
+    ELASTIC_APM_UNUSED(resultCode);
     return;
 
     failure:
@@ -201,7 +280,7 @@ ResultCode elasticApmInterceptCallsToInternalMethod( String className, String me
 
     finally:
 
-    ELASTIC_APM_LOG_DEBUG_RESULT_CODE_FUNCTION_EXIT();
+    ELASTIC_APM_LOG_DEBUG_RESULT_CODE_FUNCTION_EXIT_MSG( "className: `%s'; methodName: `%s', interceptRegistrationId: %u", className, methodName, *interceptRegistrationId );
     return resultCode;
 
     failure:
@@ -231,7 +310,7 @@ ResultCode elasticApmInterceptCallsToInternalFunctionEx( String functionName, ui
 
     finally:
 
-    ELASTIC_APM_LOG_DEBUG_RESULT_CODE_FUNCTION_EXIT_MSG( "interceptRegistrationId: %u", *interceptRegistrationId );
+    ELASTIC_APM_LOG_DEBUG_RESULT_CODE_FUNCTION_EXIT_MSG( "functionName: `%s', interceptRegistrationId: %u", functionName, *interceptRegistrationId );
     return resultCode;
 
     failure:

src/ext/lifecycle.c

@@ -449,6 +449,7 @@ void setLastPhpErrorData( int type, const char* fileName, uint32_t lineNumber, c
     tempPhpErrorData.type = type;
     tempPhpErrorData.lineNumber = lineNumber;
 
+    freeAndZeroLastPhpErrorData( &g_lastPhpErrorData );
     shallowCopyLastPhpErrorData( &tempPhpErrorData, &g_lastPhpErrorData );
     zeroLastPhpErrorData( &tempPhpErrorData );
     g_lastPhpErrorDataSet = true;

src/ext/tracer_PHP_part.c

@@ -159,11 +159,12 @@ bool tracerPhpPartInterceptedCallPreHook( uint32_t interceptRegistrationId, zend
                     , interceptedCallArgsCount + 2
                     , phpPartArgs
                     , /* out */ &preHookRetVal ) );
-    ELASTIC_APM_LOG_TRACE( "Successfully finished call to PHP part. Return value type: %u", Z_TYPE_P( &preHookRetVal ) );
+    ELASTIC_APM_LOG_TRACE( "Finished call to PHP part. Return value type: %s (%u)"
+                           , zend_get_type_by_const(Z_TYPE(preHookRetVal)), Z_TYPE(preHookRetVal) );
 
     if ( Z_TYPE( preHookRetVal ) != IS_FALSE && Z_TYPE( preHookRetVal ) != IS_TRUE )
     {
-        ELASTIC_APM_LOG_ERROR( "Call to PHP part returned value that is not bool. Return value type: %u", Z_TYPE_P( &preHookRetVal ) );
+        ELASTIC_APM_LOG_ERROR( "Call to PHP part returned value that is not bool. Return value type: %s (%u)", zend_get_type_by_const(Z_TYPE(preHookRetVal)), Z_TYPE(preHookRetVal) );
         ELASTIC_APM_SET_RESULT_CODE_AND_GOTO_FAILURE();
     }
     shouldCallPostHook = ( Z_TYPE( preHookRetVal ) == IS_TRUE );
@@ -181,10 +182,10 @@ bool tracerPhpPartInterceptedCallPreHook( uint32_t interceptRegistrationId, zend
     goto finally;
 }
 
-void tracerPhpPartInterceptedCallPostHook( uint32_t dbgInterceptRegistrationId, zval* interceptedCallRetValOrThrown )
+ResultCode tracerPhpPartInterceptedCallPostHook( zval* interceptedCallRetValOrThrown )
 {
-    ELASTIC_APM_LOG_TRACE_FUNCTION_ENTRY_MSG( "dbgInterceptRegistrationId: %u; interceptedCallRetValOrThrown type: %u"
-                                              , dbgInterceptRegistrationId, Z_TYPE_P( interceptedCallRetValOrThrown ) );
+    ELASTIC_APM_LOG_TRACE_FUNCTION_ENTRY_MSG( "interceptedCallRetValOrThrown type: %s (%u)"
+                                              , zend_get_type_by_const( Z_TYPE_P( interceptedCallRetValOrThrown ) ), Z_TYPE_P( interceptedCallRetValOrThrown ) );
 
     ResultCode resultCode;
     zval phpPartArgs[ 2 ];
@@ -206,10 +207,10 @@ void tracerPhpPartInterceptedCallPostHook( uint32_t dbgInterceptRegistrationId,
 
     finally:
 
-    ELASTIC_APM_LOG_TRACE_RESULT_CODE_FUNCTION_EXIT_MSG( "dbgInterceptRegistrationId: %u; interceptedCallRetValOrThrown type: %u."
-                                                         , dbgInterceptRegistrationId, Z_TYPE_P( interceptedCallRetValOrThrown ) );
+    ELASTIC_APM_LOG_TRACE_RESULT_CODE_FUNCTION_EXIT_MSG( "interceptedCallRetValOrThrown type: %s (%u)"
+                                                         , zend_get_type_by_const( Z_TYPE_P( interceptedCallRetValOrThrown ) ), Z_TYPE_P( interceptedCallRetValOrThrown ) );
     ELASTIC_APM_UNUSED( resultCode );
-    return;
+    return resultCode;
 
     failure:
     goto finally;

src/ext/tracer_PHP_part.h

@@ -28,6 +28,6 @@ void shutdownTracerPhpPart( const ConfigSnapshot* config );
 
 bool tracerPhpPartInterceptedCallPreHook( uint32_t interceptRegistrationId, zend_execute_data* execute_data );
 
-void tracerPhpPartInterceptedCallPostHook( uint32_t dbgInterceptRegistrationId, zval* interceptedCallRetValOrThrown );
+ResultCode tracerPhpPartInterceptedCallPostHook( zval* interceptedCallRetValOrThrown );
 
 void tracerPhpPartInterceptedCallEmptyMethod();