fix: early OpenTelemetry context propagation in invocation

runtimes/v1/azure_functions_runtime_v1/handle_event.py

@@ -156,6 +156,15 @@ async def invocation_request(request):
         fi: FunctionInfo = _functions.get_function(
             function_id)
         assert fi is not None
+
+        # Initialize context and configure OpenTelemetry before emitting
+        # invocation-scoped logs so they include trace context (Operation Id)
+        fi_context = get_context(invoc_request, fi.name,
+                                 fi.directory)
+        if (otel_manager.get_azure_monitor_available()
+                or otel_manager.get_otel_libs_available()):
+            configure_opentelemetry(fi_context)
+
         logger.info("Function name: %s, Function Type: %s",
                     fi.name,
                     ("async" if fi.is_async else "sync"))
@@ -174,9 +183,6 @@ async def invocation_request(request):
                 pb,
                 trigger_metadata=trigger_metadata)
 
-        fi_context = get_context(invoc_request, fi.name,
-                                 fi.directory)
-
         # Use local thread storage to store the invocation ID
         # for a customer's threads
         fi_context.thread_local_storage.invocation_id = invocation_id
@@ -188,9 +194,6 @@ async def invocation_request(request):
                 args[name] = Out()
 
         if fi.is_async:
-            if otel_manager.get_azure_monitor_available():
-                configure_opentelemetry(fi_context)
-
             # Not supporting Extensions
             call_result = await execute_async(fi.func, args)
         else:
@@ -232,7 +235,6 @@ async def invocation_request(request):
 
         # Actively flush customer print() function to console
         sys.stdout.flush()
-
         logger.debug("Successfully completed WorkerInvocationRequest.")
         return protos.InvocationResponse(
             invocation_id=invocation_id,

runtimes/v1/azure_functions_runtime_v1/utils/executor.py

@@ -7,8 +7,6 @@
 
 from typing import Any
 
-from ..otel import otel_manager, configure_opentelemetry
-
 
 def get_current_loop():
     return asyncio.events.get_event_loop()
@@ -31,8 +29,6 @@ def run_sync_func(invocation_id, context, func, params):
     context.thread_local_storage.invocation_id = invocation_id
     token = invocation_id_cv.set(invocation_id)
     try:
-        if otel_manager.get_azure_monitor_available():
-            configure_opentelemetry(context)
         result = functools.partial(execute_sync, func)
         return result(params)
     finally:

runtimes/v1/tests/unittests/test_executor.py

@@ -0,0 +1,57 @@
+import concurrent.futures
+import threading
+import unittest
+from unittest.mock import MagicMock
+
+from azure_functions_runtime_v1.utils.executor import (
+    invocation_id_cv,
+    run_sync_func,
+)
+
+
+class TestSyncInvocationContext(unittest.TestCase):
+
+    def setUp(self):
+        self.context = MagicMock()
+        self.context.thread_local_storage = threading.local()
+        self.executor = concurrent.futures.ThreadPoolExecutor(max_workers=1)
+
+    def tearDown(self):
+        self.executor.shutdown()
+
+    def _get_current_invocation_ids(self):
+        return (self.context.thread_local_storage.invocation_id,
+                invocation_id_cv.get())
+
+    def test_invocation_id_cleared_after_success(self):
+        observed_invocation_ids = []
+
+        def invoke():
+            observed_invocation_ids.append(self._get_current_invocation_ids())
+
+        self.executor.submit(
+            run_sync_func,
+            'test-invocation', self.context, invoke, {}).result()
+
+        remaining_invocation_ids = self.executor.submit(
+            self._get_current_invocation_ids).result()
+        self.assertEqual(
+            observed_invocation_ids,
+            [('test-invocation', 'test-invocation')])
+        self.assertEqual(remaining_invocation_ids, (None, None))
+
+    def test_invocation_id_cleared_after_exception(self):
+        def invoke():
+            self.assertEqual(
+                self._get_current_invocation_ids(),
+                ('test-invocation', 'test-invocation'))
+            raise RuntimeError('test error')
+
+        with self.assertRaisesRegex(RuntimeError, 'test error'):
+            self.executor.submit(
+                run_sync_func,
+                'test-invocation', self.context, invoke, {}).result()
+
+        remaining_invocation_ids = self.executor.submit(
+            self._get_current_invocation_ids).result()
+        self.assertEqual(remaining_invocation_ids, (None, None))

runtimes/v1/tests/unittests/test_opentelemetry.py

@@ -4,13 +4,18 @@
 
 import tests.protos as protos
 
-from azure_functions_runtime_v1.handle_event import otel_manager, worker_init_request
+from azure_functions_runtime_v1.handle_event import (
+    invocation_request,
+    otel_manager,
+    worker_init_request,
+)
 from azure_functions_runtime_v1.otel import (initialize_azure_monitor,
                                              update_opentelemetry_status)
 from azure_functions_runtime_v1.logging import logger
 from tests.utils.constants import UNIT_TESTS_FOLDER
 from tests.utils.mock_classes import FunctionRequest, Request, WorkerRequest
-from unittest.mock import MagicMock, patch
+from tests.utils import testutils
+from unittest.mock import AsyncMock, MagicMock, patch
 
 
 FUNCTION_APP_DIRECTORY = UNIT_TESTS_FOLDER / 'basic_functions'
@@ -207,3 +212,188 @@ async def test_init_request_enable_azure_monitor_disabled_app_setting(
         # Verify that WorkerOpenTelemetryEnabled capability is not set
         capabilities = init_response.capabilities
         self.assertNotIn("WorkerOpenTelemetryEnabled", capabilities)
+
+
+class TestOpenTelemetryContextPropagation(testutils.AsyncTestCase):
+    """Tests to verify OpenTelemetry context is propagated before logging in v1.
+
+    Issue #1626: OpenTelemetry context must be configured before the first
+    log is emitted in invocation_request to ensure all logs have proper
+    Operation Id in Application Insights.
+    """
+
+    def setUp(self):
+        self.call_order = []
+
+    def _track_configure_otel(self, *args, **kwargs):
+        self.call_order.append('configure_opentelemetry')
+
+    def _track_logger_info(self, *args, **kwargs):
+        self.call_order.append('logger_info')
+
+    def _make_mock_request(self, invocation_id="test-inv-id",
+                           function_id="test-func-id"):
+        """Create a minimal mock invocation request."""
+        mock_invoc = MagicMock()
+        mock_invoc.invocation_id = invocation_id
+        mock_invoc.function_id = function_id
+        mock_invoc.input_data = []
+
+        mock_request = MagicMock()
+        mock_request.request.invocation_request = mock_invoc
+        return mock_request
+
+    def _make_mock_fi(self):
+        """Create a minimal mock FunctionInfo."""
+        mock_fi = MagicMock()
+        mock_fi.name = "test_function"
+        mock_fi.is_async = True
+        mock_fi.directory = "/test/dir"
+        mock_fi.input_types = {}
+        mock_fi.output_types = {}
+        mock_fi.requires_context = False
+        mock_fi.has_return = False
+        mock_fi.return_type = None
+        return mock_fi
+
+    @patch("azure_functions_runtime_v1.handle_event"
+           ".otel_manager.get_azure_monitor_available", return_value=True)
+    @patch("azure_functions_runtime_v1.handle_event"
+           ".otel_manager.get_otel_libs_available", return_value=False)
+    @patch("azure_functions_runtime_v1.handle_event.execute_async",
+           new_callable=AsyncMock)
+    @patch("azure_functions_runtime_v1.handle_event.get_context")
+    @patch("azure_functions_runtime_v1.handle_event._functions")
+    @patch("azure_functions_runtime_v1.handle_event.configure_opentelemetry")
+    @patch("azure_functions_runtime_v1.handle_event.logger")
+    async def test_otel_configured_before_first_log_azure_monitor(
+        self,
+        mock_logger,
+        mock_configure_otel,
+        mock_functions,
+        mock_get_context,
+        mock_execute_async,
+        mock_get_otel_libs,
+        mock_get_azure_monitor,
+    ):
+        """Verify configure_opentelemetry is called before first log (Azure Monitor)."""
+        mock_logger.info.side_effect = self._track_logger_info
+        mock_configure_otel.side_effect = self._track_configure_otel
+        mock_functions.get_function.return_value = self._make_mock_fi()
+        mock_get_context.return_value = MagicMock()
+        mock_execute_async.return_value = None
+
+        try:
+            await invocation_request(self._make_mock_request())
+        except Exception:
+            pass
+
+        self.assertIn('configure_opentelemetry', self.call_order,
+                      "configure_opentelemetry should have been called")
+        self.assertIn('logger_info', self.call_order,
+                      "logger.info should have been called")
+
+        otel_index = self.call_order.index('configure_opentelemetry')
+        first_log_index = self.call_order.index('logger_info')
+        self.assertLess(
+            otel_index, first_log_index,
+            f"configure_opentelemetry (index {otel_index}) should be called "
+            f"before the first logger.info (index {first_log_index}). "
+            f"Call order: {self.call_order}"
+        )
+
+    @patch("azure_functions_runtime_v1.handle_event"
+           ".otel_manager.get_azure_monitor_available", return_value=False)
+    @patch("azure_functions_runtime_v1.handle_event"
+           ".otel_manager.get_otel_libs_available", return_value=True)
+    @patch("azure_functions_runtime_v1.handle_event.execute_async",
+           new_callable=AsyncMock)
+    @patch("azure_functions_runtime_v1.handle_event.get_context")
+    @patch("azure_functions_runtime_v1.handle_event._functions")
+    @patch("azure_functions_runtime_v1.handle_event.configure_opentelemetry")
+    @patch("azure_functions_runtime_v1.handle_event.logger")
+    async def test_otel_configured_before_first_log_otel_libs(
+        self,
+        mock_logger,
+        mock_configure_otel,
+        mock_functions,
+        mock_get_context,
+        mock_execute_async,
+        mock_get_otel_libs,
+        mock_get_azure_monitor,
+    ):
+        """Verify configure_opentelemetry is called before first log (otel libs)."""
+        mock_logger.info.side_effect = self._track_logger_info
+        mock_configure_otel.side_effect = self._track_configure_otel
+        mock_functions.get_function.return_value = self._make_mock_fi()
+        mock_get_context.return_value = MagicMock()
+        mock_execute_async.return_value = None
+
+        try:
+            await invocation_request(self._make_mock_request())
+        except Exception:
+            pass
+
+        self.assertIn('configure_opentelemetry', self.call_order,
+                      "configure_opentelemetry should have been called")
+        self.assertIn('logger_info', self.call_order,
+                      "logger.info should have been called")
+
+        otel_index = self.call_order.index('configure_opentelemetry')
+        first_log_index = self.call_order.index('logger_info')
+        self.assertLess(
+            otel_index, first_log_index,
+            f"configure_opentelemetry (index {otel_index}) should be called "
+            f"before the first logger.info (index {first_log_index}). "
+            f"Call order: {self.call_order}"
+        )
+
+    @patch("azure_functions_runtime_v1.handle_event"
+           ".otel_manager.get_azure_monitor_available", return_value=True)
+    @patch("azure_functions_runtime_v1.handle_event"
+           ".otel_manager.get_otel_libs_available", return_value=False)
+    @patch("azure_functions_runtime_v1.handle_event.run_sync_func",
+           return_value=None)
+    @patch("azure_functions_runtime_v1.handle_event.get_context")
+    @patch("azure_functions_runtime_v1.handle_event._functions")
+    @patch("azure_functions_runtime_v1.handle_event.configure_opentelemetry")
+    @patch("azure_functions_runtime_v1.handle_event.logger")
+    async def test_otel_configured_before_first_log_sync_function(
+        self,
+        mock_logger,
+        mock_configure_otel,
+        mock_functions,
+        mock_get_context,
+        mock_run_sync_func,
+        mock_get_otel_libs,
+        mock_get_azure_monitor,
+    ):
+        """Verify configure_opentelemetry is called before first log (sync function)."""
+        mock_logger.info.side_effect = self._track_logger_info
+        mock_configure_otel.side_effect = self._track_configure_otel
+        mock_fi = self._make_mock_fi()
+        mock_fi.is_async = False
+        mock_functions.get_function.return_value = mock_fi
+        invocation_context = MagicMock()
+        mock_get_context.return_value = invocation_context
+        request = self._make_mock_request()
+
+        try:
+            await invocation_request(request)
+        except Exception:
+            pass
+
+        self.assertIn('configure_opentelemetry', self.call_order,
+                      "configure_opentelemetry should have been called")
+        self.assertIn('logger_info', self.call_order,
+                      "logger.info should have been called")
+        mock_configure_otel.assert_called_once_with(invocation_context)
+
+        otel_index = self.call_order.index('configure_opentelemetry')
+        first_log_index = self.call_order.index('logger_info')
+        self.assertLess(
+            otel_index, first_log_index,
+            f"configure_opentelemetry (index {otel_index}) should be called "
+            f"before the first logger.info (index {first_log_index}). "
+            f"Call order: {self.call_order}"
+        )

runtimes/v2/azure_functions_runtime/handle_event.py

@@ -182,6 +182,15 @@ async def invocation_request(request):
         fi: FunctionInfo = _functions.get_function(
             function_id)
         assert fi is not None
+
+        # Initialize context and configure OpenTelemetry before emitting
+        # invocation-scoped logs so they include trace context (Operation Id)
+        fi_context = get_context(invoc_request, fi.name,
+                                 fi.directory)
+        if (otel_manager.get_azure_monitor_available()
+                or otel_manager.get_otel_libs_available()):
+            configure_opentelemetry(fi_context)
+
         logger.info("Function name: %s, Function Type: %s",
                     fi.name,
                     ("async" if fi.is_async else "sync"))
@@ -217,9 +226,6 @@ async def invocation_request(request):
             await sync_http_request(http_request, func_http_request)
             args[trigger_arg_name] = http_request
 
-        fi_context = get_context(invoc_request, fi.name,
-                                 fi.directory)
-
         # Use local thread storage to store the invocation ID
         # for a customer's threads
         fi_context.thread_local_storage.invocation_id = invocation_id
@@ -234,10 +240,6 @@ async def invocation_request(request):
                 args[name] = Out()
 
         if fi.is_async:
-            if (otel_manager.get_azure_monitor_available()
-                    or otel_manager.get_otel_libs_available()):
-                configure_opentelemetry(fi_context)
-
             # Extensions are not supported
             call_result = await execute_async(fi.func, args)
         else:

runtimes/v2/azure_functions_runtime/utils/executor.py

@@ -6,8 +6,6 @@
 
 from typing import Any
 
-from ..otel import otel_manager, configure_opentelemetry
-
 
 def get_current_loop():
     return asyncio.events.get_event_loop()
@@ -30,9 +28,6 @@ def run_sync_func(invocation_id, context, func, params):
     context.thread_local_storage.invocation_id = invocation_id
     token = invocation_id_cv.set(invocation_id)
     try:
-        if (otel_manager.get_azure_monitor_available()
-                or otel_manager.get_otel_libs_available()):
-            configure_opentelemetry(context)
         result = functools.partial(execute_sync, func)
         return result(params)
     finally: