Fix case when process fork happens during request processing (#857)

* Start thread for background backend communications on demand

and not on PHP extension request-init notification to correctly handle the situation when process forked after request-init notification

* Add update-specs updatecli workflow (#861)

* Fix sha source (#864)

* Use composite action for updatecli workflow (#865)

* Use composite action

* Add env

* Detect PID change (i.e., child fork) at every entry to agent code

* Migrate Jenkinsfile 2 GH Actions Workflow (#863)

* Migrate Jenkinsfile to GH Actions Workflow

* Fix triggers

* Update .github/workflows/test.yml

* Fix

* Fix php-upgrade

* Add opentelemetry

* Rename job

* Add timeout

* Adjust max-parallel

* Fix needs

* Fix

* Move php rows to top

So they are triggered first in the matrix and should optimize the workflow time

* Move lifecycle on prod server rows to the top

Should also optimze workflow time

* Add test-reporter

* Remove debugging step

* Update .github/workflows/test-reporter.yml

Co-authored-by: Victor Martinez <victormartinezrubio@gmail.com>

* Migrate snapshoty

* Extract snapshoty into distinct workflow

* Update .github/workflows/snapshoty.yml

* Run snapshoty only on main

---------

Co-authored-by: Victor Martinez <victormartinezrubio@gmail.com>

* action: run loop workflow (#867)

* Start thread for background backend communications on demand

and not on PHP extension request-init notification to correctly handle the situation when process forked after request-init notification

* Detect PID change (i.e., child fork) at every entry to agent code

---------

Co-authored-by: Jan Calanog <jan.calanog@elastic.co>
Co-authored-by: Victor Martinez <victormartinezrubio@gmail.com>

Author: 3 people

src/ext/ResultCode.h

@@ -28,6 +28,7 @@ enum ResultCode
     resultOutOfMemory,
     resultInvalidFormat,
     resultCurlFailure,
+    resultSyncObjUseAfterFork,
     resultFailure
 };
 typedef enum ResultCode ResultCode;
@@ -45,6 +46,12 @@ static inline String resultCodeToString( ResultCode resultCode )
         case resultInvalidFormat:
             return "resultInvalidFormat";
 
+        case resultCurlFailure:
+            return "resultCurlFailure";
+
+        case resultSyncObjUseAfterFork:
+            return "resultSyncObjUseAfterFork";
+
         case resultFailure:
             return "resultFailure";
 

src/ext/Tracer.c

@@ -69,7 +69,6 @@ ResultCode ensureLoggerHasLatestConfig( Logger* logger, const ConfigSnapshot* co
     ELASTIC_APM_CALL_IF_FAILED_GOTO( reconfigureLogger( logger, &loggerConfig, config->logLevel ) );
 
     resultCode = resultSuccess;
-
     finally:
     return resultCode;
 

src/ext/backend_comm.c

@@ -418,7 +418,6 @@ static void freeDataToSendQueue( DataToSendQueue* dataQueue )
 
 struct BackgroundBackendComm
 {
-    int refCount;
     Mutex* mutex;
     ConditionVariable* condVar;
     Thread* thread;
@@ -730,8 +729,10 @@ void* backgroundBackendCommThreadFunc( void* arg )
     goto finally;
 }
 
-ResultCode unwindBackgroundBackendComm( BackgroundBackendComm** backgroundBackendCommOutPtr, const TimeSpec* timeoutAbsUtc )
+ResultCode unwindBackgroundBackendComm( BackgroundBackendComm** backgroundBackendCommOutPtr, const TimeSpec* timeoutAbsUtc, bool isCreatedByThisProcess )
 {
+    ELASTIC_APM_LOG_DEBUG_FUNCTION_ENTRY_MSG( "isCreatedByThisProcess: %s", boolToString( isCreatedByThisProcess ) );
+
     ELASTIC_APM_ASSERT_VALID_PTR( backgroundBackendCommOutPtr );
     // ELASTIC_APM_ASSERT_VALID_PTR( timeoutAbsUtc ); <- timeoutAbsUtc can be NULL
 
@@ -744,12 +745,20 @@ ResultCode unwindBackgroundBackendComm( BackgroundBackendComm** backgroundBacken
         goto finally;
     }
 
+    if ( ! isCreatedByThisProcess )
+    {
+        ELASTIC_APM_LOG_DEBUG( "Deallocating memory related to background communication data structures inherited from parent process after fork"
+                               " without actually properly destroying synchronization primitives since it's impossible to do in child process"
+                               "; parent PID: %d"
+                               , (int)getParentProcessId() );
+    }
+
     if ( backgroundBackendComm->thread != NULL )
     {
         void* backgroundBackendCommThreadFuncRetVal = NULL;
         bool hasTimedOut;
         ELASTIC_APM_CALL_IF_FAILED_GOTO(
-                timedJoinAndDeleteThread( &( backgroundBackendComm->thread ), &backgroundBackendCommThreadFuncRetVal, timeoutAbsUtc, &hasTimedOut, __FUNCTION__ ) );
+                timedJoinAndDeleteThread( &( backgroundBackendComm->thread ), &backgroundBackendCommThreadFuncRetVal, timeoutAbsUtc, isCreatedByThisProcess, &hasTimedOut, __FUNCTION__ ) );
         if ( hasTimedOut )
         {
             ELASTIC_APM_LOG_ERROR( "Join to thread for background backend communications timed out - skipping the rest of cleanup and exiting" );
@@ -759,7 +768,7 @@ ResultCode unwindBackgroundBackendComm( BackgroundBackendComm** backgroundBacken
 
     if ( backgroundBackendComm->condVar != NULL )
     {
-        ELASTIC_APM_CALL_IF_FAILED_GOTO( deleteConditionVariable( &( backgroundBackendComm->condVar ) ) );
+        ELASTIC_APM_CALL_IF_FAILED_GOTO( deleteConditionVariable( &( backgroundBackendComm->condVar ), isCreatedByThisProcess ) );
     }
 
     if ( backgroundBackendComm->mutex != NULL )
@@ -772,13 +781,13 @@ ResultCode unwindBackgroundBackendComm( BackgroundBackendComm** backgroundBacken
     ELASTIC_APM_FREE_INSTANCE_AND_SET_TO_NULL( BackgroundBackendComm, *backgroundBackendCommOutPtr );
 
     finally:
+    ELASTIC_APM_LOG_DEBUG_RESULT_CODE_FUNCTION_EXIT();
     return resultCode;
 
     failure:
     goto finally;
 }
 
-static Mutex* g_backgroundBackendCommMutex = NULL;
 static BackgroundBackendComm* g_backgroundBackendComm = NULL;
 
 static bool deriveAsyncBackendComm( const ConfigSnapshot* config, String* dbgReason )
@@ -799,47 +808,6 @@ static bool deriveAsyncBackendComm( const ConfigSnapshot* config, String* dbgRea
     return true;
 }
 
-ResultCode backgroundBackendCommOnModuleInit( const ConfigSnapshot* config )
-{
-    ELASTIC_APM_LOG_DEBUG_FUNCTION_ENTRY_MSG( "g_backgroundBackendCommMutex: %p; g_backgroundBackendComm: %p"
-                                              , g_backgroundBackendCommMutex, g_backgroundBackendComm );
-
-    ResultCode resultCode;
-
-    if ( g_backgroundBackendCommMutex != NULL )
-    {
-        ELASTIC_APM_LOG_ERROR( "Unexpected state: g_backgroundBackendCommMutex != NULL" );
-        ELASTIC_APM_SET_RESULT_CODE_AND_GOTO_FAILURE();
-    }
-
-    if ( g_backgroundBackendComm != NULL )
-    {
-        ELASTIC_APM_LOG_ERROR( "Unexpected state: g_backgroundBackendComm != NULL" );
-        ELASTIC_APM_SET_RESULT_CODE_AND_GOTO_FAILURE();
-    }
-
-    String dbgAsyncBackendCommReason = NULL;
-    if ( ! deriveAsyncBackendComm( config, &dbgAsyncBackendCommReason ) )
-    {
-        ELASTIC_APM_LOG_DEBUG( "async_backend_comm (asyncBackendComm) configuration option is %s - no need to start background backend comm", dbgAsyncBackendCommReason );
-        resultCode = resultSuccess;
-        goto finally;
-    }
-
-    ELASTIC_APM_CALL_IF_FAILED_GOTO( newMutex( &( g_backgroundBackendCommMutex ), /* dbgDesc */ "g_backgroundBackendCommMutex" ) );
-
-    finally:
-    ELASTIC_APM_LOG_DEBUG_RESULT_CODE_FUNCTION_EXIT();
-    return resultCode;
-
-    failure:
-    if ( g_backgroundBackendCommMutex != NULL )
-    {
-        deleteMutex( &g_backgroundBackendCommMutex );
-    }
-    goto finally;
-}
-
 ResultCode newBackgroundBackendComm( const ConfigSnapshot* config, BackgroundBackendComm** backgroundBackendCommOut )
 {
     ELASTIC_APM_LOG_DEBUG_FUNCTION_ENTRY();
@@ -848,7 +816,6 @@ ResultCode newBackgroundBackendComm( const ConfigSnapshot* config, BackgroundBac
     BackgroundBackendComm* backgroundBackendComm = NULL;
 
     ELASTIC_APM_MALLOC_INSTANCE_IF_FAILED_GOTO( BackgroundBackendComm, /* out */ backgroundBackendComm );
-    backgroundBackendComm->refCount = 1;
     backgroundBackendComm->condVar = NULL;
     backgroundBackendComm->mutex = NULL;
     backgroundBackendComm->thread = NULL;
@@ -860,7 +827,6 @@ ResultCode newBackgroundBackendComm( const ConfigSnapshot* config, BackgroundBac
     ELASTIC_APM_CALL_IF_FAILED_GOTO( newMutex( &( backgroundBackendComm->mutex ), /* dbgDesc */ "Background backend communications" ) );
     ELASTIC_APM_CALL_IF_FAILED_GOTO( newConditionVariable( &( backgroundBackendComm->condVar ), /* dbgDesc */ "Background backend communications" ) );
 
-    backgroundBackendComm->refCount = 2;
     resultCode = newThread( &( backgroundBackendComm->thread )
                             , &backgroundBackendCommThreadFunc
                             , /* threadFuncArg: */ backgroundBackendComm
@@ -869,10 +835,6 @@ ResultCode newBackgroundBackendComm( const ConfigSnapshot* config, BackgroundBac
     {
         ELASTIC_APM_LOG_DEBUG( "Started thread for background backend communications; thread ID: %"PRIu64, getThreadId( backgroundBackendComm->thread ) );
     }
-    else
-    {
-        --backgroundBackendComm->refCount;
-    }
 
     resultCode = resultSuccess;
     *backgroundBackendCommOut = backgroundBackendComm;
@@ -882,31 +844,15 @@ ResultCode newBackgroundBackendComm( const ConfigSnapshot* config, BackgroundBac
     return resultCode;
 
     failure:
-    unwindBackgroundBackendComm( &backgroundBackendComm, /* timeoutAbsUtc: */ NULL );
+    unwindBackgroundBackendComm( &backgroundBackendComm, /* timeoutAbsUtc: */ NULL, /* isCreatedByThisProcess */ true );
     goto finally;
 }
 
-ResultCode backgroundBackendCommOnRequestInit( const ConfigSnapshot* config )
+ResultCode backgroundBackendCommEnsureInited( const ConfigSnapshot* config )
 {
-    ELASTIC_APM_LOG_DEBUG_FUNCTION_ENTRY_MSG( "g_backgroundBackendCommMutex: %p", g_backgroundBackendCommMutex );
+    ELASTIC_APM_LOG_DEBUG_FUNCTION_ENTRY();
 
     ResultCode resultCode;
-    bool shouldUnlockMutex = false;
-
-    String dbgAsyncBackendCommReason = NULL;
-    if ( ! deriveAsyncBackendComm( config, &dbgAsyncBackendCommReason ) )
-    {
-        ELASTIC_APM_LOG_DEBUG( "async_backend_comm (asyncBackendComm) configuration option is %s - no need to start background backend comm", dbgAsyncBackendCommReason );
-        resultCode = resultSuccess;
-        goto finally;
-    }
-
-    if ( g_backgroundBackendCommMutex == NULL )
-    {
-        ELASTIC_APM_LOG_ERROR( "Unexpected state: g_backgroundBackendCommMutex == NULL" );
-        ELASTIC_APM_SET_RESULT_CODE_AND_GOTO_FAILURE();
-    }
-    ELASTIC_APM_CALL_IF_FAILED_GOTO( lockMutex( g_backgroundBackendCommMutex, &shouldUnlockMutex, __FUNCTION__ ) );
 
     if ( g_backgroundBackendComm == NULL )
     {
@@ -916,7 +862,6 @@ ResultCode backgroundBackendCommOnRequestInit( const ConfigSnapshot* config )
     resultCode = resultSuccess;
 
     finally:
-    unlockMutex( g_backgroundBackendCommMutex, &shouldUnlockMutex, __FUNCTION__ );
     ELASTIC_APM_LOG_DEBUG_RESULT_CODE_FUNCTION_EXIT();
     return resultCode;
 
@@ -965,19 +910,16 @@ void backgroundBackendCommOnModuleShutdown()
         return;
     }
 
-    ELASTIC_APM_ASSERT( g_backgroundBackendCommMutex != NULL, "%p", g_backgroundBackendCommMutex );
-
     ResultCode resultCode;
     TimeSpec shouldExitBy;
 
     ELASTIC_APM_CALL_IF_FAILED_GOTO( signalBackgroundBackendCommThreadToExit( backgroundBackendComm, /* out */ &shouldExitBy ) );
-    ELASTIC_APM_CALL_IF_FAILED_GOTO( unwindBackgroundBackendComm( &backgroundBackendComm, &shouldExitBy ) );
+    ELASTIC_APM_CALL_IF_FAILED_GOTO( unwindBackgroundBackendComm( &backgroundBackendComm, &shouldExitBy, /* isCreatedByThisProcess */ true ) );
     resultCode = resultSuccess;
 
     finally:
 
     g_backgroundBackendComm = NULL;
-    ELASTIC_APM_CALL_IF_FAILED_GOTO( deleteMutex( &g_backgroundBackendCommMutex ) );
     return;
 
     failure:
@@ -1082,11 +1024,8 @@ ResultCode sendEventsToApmServerWithDataConvertedForSync(
                                        , serializedEvents ) );
 
     resultCode = resultSuccess;
-
     finally:
-
     freeMallocedStringBuffer( /* in,out */ &userAgentHttpHeaderWithTermNull );
-
     return resultCode;
 
     failure:
@@ -1100,7 +1039,9 @@ ResultCode sendEventsToApmServer(
         , StringView userAgentHttpHeader
         , StringView serializedEvents )
 {
+    ResultCode resultCode;
     long serverTimeoutMillisecondsLong = (long) ceil( serverTimeoutMilliseconds );
+
     ELASTIC_APM_LOG_DEBUG(
             "Handling request to send events..."
             " disableSend: %s"
@@ -1113,15 +1054,49 @@ ResultCode sendEventsToApmServer(
             , (UInt64) serializedEvents.length, (int) serializedEvents.length, serializedEvents.begin );
 
     String dbgAsyncBackendCommReason = NULL;
-    if ( ! deriveAsyncBackendComm( config, &dbgAsyncBackendCommReason ) )
+    bool shouldSendAsync = deriveAsyncBackendComm( config, &dbgAsyncBackendCommReason );
+    ELASTIC_APM_LOG_DEBUG( "async_backend_comm (asyncBackendComm) configuration option is %s - sending events %s"
+                           , dbgAsyncBackendCommReason, ( shouldSendAsync ? "asynchronously" : "synchronously" ) );
+    if ( shouldSendAsync )
+    {
+        ELASTIC_APM_CALL_IF_FAILED_GOTO( backgroundBackendCommEnsureInited( config ) );
+        ELASTIC_APM_CALL_IF_FAILED_GOTO( enqueueEventsToSendToApmServer( disableSend, serverTimeoutMilliseconds, userAgentHttpHeader, serializedEvents ) );
+    }
+    else
+    {
+        ELASTIC_APM_CALL_IF_FAILED_GOTO( sendEventsToApmServerWithDataConvertedForSync(
+                disableSend
+                , serverTimeoutMilliseconds
+                , config
+                , userAgentHttpHeader
+                , serializedEvents ) );
+    }
+
+    resultCode = resultSuccess;
+    finally:
+    ELASTIC_APM_LOG_DEBUG_RESULT_CODE_FUNCTION_EXIT();
+    return resultCode;
+
+    failure:
+    goto finally;
+}
+
+ResultCode resetBackgroundBackendCommStateInForkedChild()
+{
+    ELASTIC_APM_LOG_DEBUG_FUNCTION_ENTRY_MSG( "g_backgroundBackendComm %s NULL", (g_backgroundBackendComm == NULL) ? "==" : "!=" );
+
+    ResultCode resultCode;
+
+    if ( g_backgroundBackendComm != NULL )
     {
-        ELASTIC_APM_LOG_DEBUG( "async_backend_comm (asyncBackendComm) configuration option is %s - sending events synchronously", dbgAsyncBackendCommReason );
-        return sendEventsToApmServerWithDataConvertedForSync( disableSend
-                                                              , serverTimeoutMilliseconds
-                                                              , config
-                                                              , userAgentHttpHeader
-                                                              , serializedEvents );
+        ELASTIC_APM_CALL_IF_FAILED_GOTO( unwindBackgroundBackendComm( &g_backgroundBackendComm, /* timeoutAbsUtc: */ NULL, /* isCreatedByThisProcess */ false ) );
     }
 
-    return enqueueEventsToSendToApmServer( disableSend, serverTimeoutMilliseconds, userAgentHttpHeader, serializedEvents );
-}
+    resultCode = resultSuccess;
+    finally:
+    ELASTIC_APM_LOG_DEBUG_RESULT_CODE_FUNCTION_EXIT();
+    return resultCode;
+
+    failure:
+    goto finally;
+}

src/ext/backend_comm.h

@@ -23,10 +23,6 @@
 #include "ConfigManager.h"
 #include "ResultCode.h"
 
-ResultCode backgroundBackendCommOnModuleInit( const ConfigSnapshot* config );
-
-ResultCode backgroundBackendCommOnRequestInit( const ConfigSnapshot* config );
-
 ResultCode sendEventsToApmServer(
         bool disableSend
         , double serverTimeoutMilliseconds
@@ -35,3 +31,5 @@ ResultCode sendEventsToApmServer(
         , StringView serializedEvents );
 
 void backgroundBackendCommOnModuleShutdown();
+
+ResultCode resetBackgroundBackendCommStateInForkedChild();