Skip to content

Commit 1b1f64b

Browse files
Python: Avoid logging function argument values (#14574)
### Motivation and Context <!-- Thank you for your contribution to the semantic-kernel repo! Please help reviewers and future users, providing the following information: 1. Why is this change required? 2. What problem does it solve? 3. What scenario does it contribute to? 4. If it fixes an open issue, please link to the issue here. --> Function invocation diagnostics currently include complete argument, result, or exception values at INFO, DEBUG, or ERROR level. This change keeps invocation diagnostics useful while avoiding recording those values in ordinary application logs or non-sensitive function spans. ### Description <!-- Describe your changes, the overall approach, the underlying design. These notes will help understanding how your code works. Thanks! --> - Log automatic function identity at INFO without argument values. - Log argument counts, result presence, and error type instead of function values. - Keep raw exception details in function spans only when sensitive diagnostics are explicitly enabled. - Add focused regression coverage for automatic invocation, direct and streaming function invocation, and synchronous/asynchronous template helpers. Validation: - `uv build --out-dir /tmp/semantic-kernel-pr-review-build` — passed; built the source distribution and wheel. - `uv run pre-commit run --files semantic_kernel/kernel.py semantic_kernel/functions/kernel_function.py semantic_kernel/functions/kernel_function_log_messages.py semantic_kernel/prompt_template/utils/template_function_helpers.py semantic_kernel/utils/telemetry/model_diagnostics/function_tracer.py tests/unit/kernel/test_kernel.py tests/unit/functions/test_kernel_function_from_method.py tests/unit/prompt_template/test_template_helper.py` — passed all applicable hooks. - `uv run pytest tests/unit/kernel/test_kernel.py tests/unit/functions/test_kernel_function_from_method.py tests/unit/prompt_template/test_template_helper.py` — 132 passed. - `uv run pytest tests/unit/utils/model_diagnostics/test_trace_chat_completion.py tests/unit/utils/model_diagnostics/test_trace_streaming_chat_completion.py tests/unit/utils/model_diagnostics/test_trace_text_completion.py tests/unit/utils/model_diagnostics/test_trace_streaming_text_completion.py` — 28 passed. The full unit-test suite was not run locally; the targeted files cover each changed logging and tracing path. ### Contribution Checklist <!-- Before submitting this PR, please make sure: --> - [x] The code builds clean without any errors or warnings - [x] The PR follows the [SK Contribution Guidelines](https://github.com/microsoft/semantic-kernel/blob/main/CONTRIBUTING.md) and the [pre-submission formatting script](https://github.com/microsoft/semantic-kernel/blob/main/CONTRIBUTING.md#development-scripts) raises no violations - [ ] All unit tests pass, and I have added new tests where possible - [x] I didn't break anyone 😄
1 parent 11f0723 commit 1b1f64b

8 files changed

Lines changed: 252 additions & 22 deletions

File tree

‎python/semantic_kernel/functions/kernel_function.py‎

Lines changed: 9 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -401,11 +401,15 @@ def _handle_exception(self, current_span: trace.Span, exception: Exception, attr
401401
exception (Exception): The exception.
402402
attributes (Attributes): The attributes to be modified.
403403
"""
404-
attributes[ERROR_TYPE] = type(exception).__name__
405-
406-
current_span.record_exception(exception)
407-
current_span.set_attribute(ERROR_TYPE, type(exception).__name__)
408-
current_span.set_status(trace.StatusCode.ERROR, description=str(exception))
404+
error_type = type(exception).__name__
405+
attributes[ERROR_TYPE] = error_type
406+
407+
current_span.set_attribute(ERROR_TYPE, error_type)
408+
if function_tracer.are_sensitive_events_enabled():
409+
current_span.record_exception(exception)
410+
current_span.set_status(trace.StatusCode.ERROR, description=str(exception))
411+
else:
412+
current_span.set_status(trace.StatusCode.ERROR)
409413

410414
KernelFunctionLogMessages.log_function_error(logger, exception)
411415

‎python/semantic_kernel/functions/kernel_function_log_messages.py‎

Lines changed: 5 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -20,8 +20,8 @@ def log_function_invoking(logger: Logger, kernel_function_name: str):
2020

2121
@staticmethod
2222
def log_function_arguments(logger: Logger, arguments: KernelArguments):
23-
"""Log message when a kernel function is invoked."""
24-
logger.debug("Function arguments: %s", arguments)
23+
"""Log the number of arguments provided to a kernel function."""
24+
logger.debug("Function arguments provided: %d.", len(arguments))
2525

2626
@staticmethod
2727
def log_function_invoked_success(logger: Logger, kernel_function_name: str):
@@ -30,22 +30,19 @@ def log_function_invoked_success(logger: Logger, kernel_function_name: str):
3030

3131
@staticmethod
3232
def log_function_result_value(logger: Logger, function_result: FunctionResult | None):
33-
"""Log message when a kernel function result is returned."""
33+
"""Log whether a kernel function returned a result."""
3434
if not logger.isEnabledFor(logging.DEBUG):
3535
return
3636

3737
if function_result is not None:
38-
try:
39-
logger.debug("Function result: %s", function_result)
40-
except Exception:
41-
logger.error("Function result: Failed to convert result value to string")
38+
logger.debug("Function result available.")
4239
else:
4340
logger.debug("Function result: None")
4441

4542
@staticmethod
4643
def log_function_error(logger: Logger, error: Exception):
4744
"""Log message when a kernel function fails."""
48-
logger.error("Function failed. Error: %s", error)
45+
logger.error("Function failed. Error type: %s.", type(error).__name__)
4946

5047
@staticmethod
5148
def log_function_completed(logger: Logger, duration: float):

‎python/semantic_kernel/kernel.py‎

Lines changed: 6 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -423,7 +423,7 @@ async def invoke_function_call(
423423
chat_history.add_message(message=frc.to_chat_message_content())
424424
return None
425425

426-
logger.info(f"Calling {function_call.name} function with args: {function_call.arguments}")
426+
logger.info("Calling %s function.", function_call.name)
427427

428428
_rebuild_auto_function_invocation_context()
429429
invocation_context = AutoFunctionInvocationContext(
@@ -475,7 +475,11 @@ async def _inner_auto_function_invoke_handler(self, context: AutoFunctionInvocat
475475
if result:
476476
context.function_result = result
477477
except Exception as exc:
478-
logger.exception(f"Error invoking function {context.function.fully_qualified_name}: {exc}.")
478+
logger.error(
479+
"Error invoking function %s. Error type: %s.",
480+
context.function.fully_qualified_name,
481+
type(exc).__name__,
482+
)
479483
value = f"An error occurred while invoking the function {context.function.fully_qualified_name}: {exc}"
480484
if context.function_result is not None:
481485
context.function_result.value = value

‎python/semantic_kernel/prompt_template/utils/template_function_helpers.py‎

Lines changed: 9 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -96,13 +96,15 @@ def func(*args, **kwargs):
9696
actual_args = args
9797

9898
if this is not None:
99-
logger.debug(f"Handlebars context with `this`: {this}")
99+
logger.debug("Handlebars context with `this`.")
100100
else:
101101
logger.debug("Jinja2 context or Handlebars context without `this`")
102102

103103
logger.debug(
104-
f"Invoking function {function.metadata.fully_qualified_name} "
105-
f"with args: {actual_args} and kwargs: {kwargs} and this: {this}."
104+
"Invoking function %s with positional argument count %d and keyword argument count %d.",
105+
function.metadata.fully_qualified_name,
106+
len(actual_args),
107+
len(kwargs),
106108
)
107109

108110
result = asyncio.run(function.invoke(kernel=kernel, arguments=arguments))
@@ -131,7 +133,10 @@ async def func(*args, **kwargs):
131133
arguments.update(base_arguments)
132134
arguments.update(kwargs)
133135
logger.debug(
134-
f"Invoking function {function.metadata.fully_qualified_name} with args: {arguments} and kwargs: {kwargs}."
136+
"Invoking function %s with positional argument count %d and keyword argument count %d.",
137+
function.metadata.fully_qualified_name,
138+
len(args),
139+
len(kwargs),
135140
)
136141
result = await function.invoke(kernel=kernel, arguments=arguments)
137142
if allow_dangerously_set_content:

‎python/semantic_kernel/utils/telemetry/model_diagnostics/function_tracer.py‎

Lines changed: 6 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -62,4 +62,9 @@ def start_as_current_span(
6262
if function.description:
6363
attributes[TOOL_DESCRIPTION] = function.description
6464

65-
return tracer.start_as_current_span(f"{OPERATION_NAME} {function.fully_qualified_name}", attributes=attributes)
65+
return tracer.start_as_current_span(
66+
f"{OPERATION_NAME} {function.fully_qualified_name}",
67+
attributes=attributes,
68+
record_exception=False,
69+
set_status_on_exception=False,
70+
)

‎python/tests/unit/functions/test_kernel_function_from_method.py‎

Lines changed: 116 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1,9 +1,13 @@
11
# Copyright (c) Microsoft. All rights reserved.
2+
import logging
23
from collections.abc import AsyncGenerator, Iterable
4+
from contextlib import nullcontext
5+
from importlib import import_module
36
from typing import Annotated, Any
4-
from unittest.mock import Mock
7+
from unittest.mock import Mock, patch
58

69
import pytest
10+
from opentelemetry.trace import StatusCode
711

812
from semantic_kernel.connectors.ai.open_ai.services.open_ai_chat_completion import OpenAIChatCompletion
913
from semantic_kernel.exceptions import FunctionExecutionException, FunctionInitializationError
@@ -18,6 +22,8 @@
1822
from semantic_kernel.kernel import Kernel
1923
from semantic_kernel.kernel_pydantic import KernelBaseModel
2024

25+
kernel_function_module = import_module("semantic_kernel.functions.kernel_function")
26+
2127

2228
class CustomType(KernelBaseModel):
2329
id: str
@@ -177,6 +183,115 @@ def non_async_function() -> str:
177183
pass
178184

179185

186+
async def test_invoke_logs_argument_count_without_values(kernel: Kernel, caplog):
187+
secret = "SYNTHETIC_SECRET_VALUE"
188+
189+
@kernel_function
190+
def echo(value: str) -> str:
191+
return value
192+
193+
native_function = KernelFunction.from_method(method=echo, plugin_name="MockPlugin")
194+
195+
with caplog.at_level(logging.DEBUG, logger="semantic_kernel.functions.kernel_function"):
196+
result = await native_function.invoke(kernel=kernel, arguments=KernelArguments(value=secret))
197+
198+
messages = [
199+
record.getMessage() for record in caplog.records if record.name == "semantic_kernel.functions.kernel_function"
200+
]
201+
assert result.value == secret
202+
assert secret not in "\n".join(messages)
203+
assert "Function arguments provided: 1." in messages
204+
assert "Function result available." in messages
205+
206+
207+
@pytest.mark.parametrize("streaming", [False, True])
208+
async def test_invoke_failure_omits_exception_value_without_sensitive_diagnostics(
209+
kernel: Kernel, caplog, streaming: bool
210+
):
211+
secret = "SYNTHETIC_SECRET_VALUE"
212+
213+
if streaming:
214+
215+
@kernel_function
216+
def fail(value: str) -> Iterable[str]:
217+
if value:
218+
raise ValueError(value)
219+
yield ""
220+
221+
else:
222+
223+
@kernel_function
224+
def fail(value: str) -> str:
225+
raise ValueError(value)
226+
227+
native_function = KernelFunction.from_method(method=fail, plugin_name="MockPlugin")
228+
span = Mock()
229+
230+
with (
231+
patch.object(
232+
kernel_function_module.tracer,
233+
"start_as_current_span",
234+
return_value=nullcontext(span),
235+
) as start_span,
236+
patch.object(
237+
kernel_function_module.function_tracer,
238+
"are_sensitive_events_enabled",
239+
return_value=False,
240+
),
241+
caplog.at_level(logging.ERROR, logger="semantic_kernel.functions.kernel_function"),
242+
pytest.raises(ValueError, match=secret),
243+
):
244+
if streaming:
245+
async for _ in native_function.invoke_stream(kernel=kernel, arguments=KernelArguments(value=secret)):
246+
pass
247+
else:
248+
await native_function.invoke(kernel=kernel, arguments=KernelArguments(value=secret))
249+
250+
messages = [
251+
record.getMessage() for record in caplog.records if record.name == "semantic_kernel.functions.kernel_function"
252+
]
253+
assert secret not in "\n".join(messages)
254+
assert "Function failed. Error type: ValueError." in messages
255+
assert start_span.call_args.kwargs["record_exception"] is False
256+
assert start_span.call_args.kwargs["set_status_on_exception"] is False
257+
span.record_exception.assert_not_called()
258+
span.set_status.assert_called_once_with(StatusCode.ERROR)
259+
260+
261+
async def test_invoke_failure_records_exception_with_sensitive_diagnostics(kernel: Kernel, caplog):
262+
secret = "SYNTHETIC_SECRET_VALUE"
263+
264+
@kernel_function
265+
def fail(value: str) -> str:
266+
raise ValueError(value)
267+
268+
native_function = KernelFunction.from_method(method=fail, plugin_name="MockPlugin")
269+
span = Mock()
270+
271+
with (
272+
patch.object(
273+
kernel_function_module.tracer,
274+
"start_as_current_span",
275+
return_value=nullcontext(span),
276+
),
277+
patch.object(
278+
kernel_function_module.function_tracer,
279+
"are_sensitive_events_enabled",
280+
return_value=True,
281+
),
282+
caplog.at_level(logging.ERROR, logger="semantic_kernel.functions.kernel_function"),
283+
pytest.raises(ValueError, match=secret) as exc_info,
284+
):
285+
await native_function.invoke(kernel=kernel, arguments=KernelArguments(value=secret))
286+
287+
messages = [
288+
record.getMessage() for record in caplog.records if record.name == "semantic_kernel.functions.kernel_function"
289+
]
290+
assert secret not in "\n".join(messages)
291+
span.record_exception.assert_called_once_with(exc_info.value)
292+
span.set_status.assert_called_once_with(StatusCode.ERROR, description=secret)
293+
294+
180295
async def test_invoke_async(kernel: Kernel):
181296
@kernel_function()
182297
async def async_function() -> str:

‎python/tests/unit/kernel/test_kernel.py‎

Lines changed: 56 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,6 @@
11
# Copyright (c) Microsoft. All rights reserved.
22

3+
import logging
34
import os
45
import tempfile
56
from collections.abc import Callable
@@ -298,6 +299,61 @@ async def test_invoke_function_call(kernel: Kernel, get_tool_call_mock):
298299
)
299300

300301

302+
async def test_invoke_function_call_does_not_log_argument_values(kernel: Kernel, caplog):
303+
secret = "SYNTHETIC_SECRET_VALUE"
304+
305+
class TestPlugin:
306+
@kernel_function
307+
def echo(self, value: str) -> str:
308+
return value
309+
310+
kernel.add_plugin(TestPlugin(), plugin_name="test")
311+
312+
caplog.set_level(logging.INFO, logger="semantic_kernel.kernel")
313+
caplog.set_level(logging.DEBUG, logger="semantic_kernel.functions.kernel_function")
314+
await kernel.invoke_function_call(
315+
function_call=FunctionCallContent(name="test-echo", arguments={"value": secret}),
316+
chat_history=ChatHistory(),
317+
function_behavior=FunctionChoiceBehavior.Auto(),
318+
)
319+
320+
messages = [
321+
record.getMessage()
322+
for record in caplog.records
323+
if record.name in {"semantic_kernel.kernel", "semantic_kernel.functions.kernel_function"}
324+
]
325+
assert secret not in "\n".join(messages)
326+
assert "Calling test-echo function." in messages
327+
328+
329+
async def test_invoke_function_call_does_not_log_exception_values(kernel: Kernel, caplog):
330+
secret = "SYNTHETIC_SECRET_VALUE"
331+
332+
class TestPlugin:
333+
@kernel_function
334+
def fail(self, value: str) -> str:
335+
raise ValueError(value)
336+
337+
kernel.add_plugin(TestPlugin(), plugin_name="test")
338+
339+
caplog.set_level(logging.ERROR, logger="semantic_kernel.kernel")
340+
caplog.set_level(logging.ERROR, logger="semantic_kernel.functions.kernel_function")
341+
await kernel.invoke_function_call(
342+
function_call=FunctionCallContent(name="test-fail", arguments={"value": secret}),
343+
chat_history=ChatHistory(),
344+
function_behavior=FunctionChoiceBehavior.Auto(),
345+
)
346+
347+
messages = [
348+
record.getMessage()
349+
for record in caplog.records
350+
if record.name in {"semantic_kernel.kernel", "semantic_kernel.functions.kernel_function"}
351+
]
352+
assert secret not in "\n".join(messages)
353+
assert "Function failed. Error type: ValueError." in messages
354+
assert "Error invoking function test-fail. Error type: ValueError." in messages
355+
356+
301357
class LightsPlugin:
302358
lights = [
303359
{"id": 1, "name": "Table Lamp", "is_on": False},

‎python/tests/unit/prompt_template/test_template_helper.py‎

Lines changed: 45 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1,11 +1,13 @@
11
# Copyright (c) Microsoft. All rights reserved.
22

3+
import logging
4+
35
import pytest
46

57
from semantic_kernel.functions import kernel_function
68
from semantic_kernel.functions.kernel_function_from_method import KernelFunctionFromMethod
79
from semantic_kernel.kernel import Kernel
8-
from semantic_kernel.prompt_template.const import JINJA2_TEMPLATE_FORMAT_NAME
10+
from semantic_kernel.prompt_template.const import HANDLEBARS_TEMPLATE_FORMAT_NAME, JINJA2_TEMPLATE_FORMAT_NAME
911
from semantic_kernel.prompt_template.utils.template_function_helpers import create_template_helper_from_function
1012

1113

@@ -26,6 +28,48 @@ def test_create_helpers(kernel: Kernel):
2628
assert int(str(result(x=1))) == 2
2729

2830

31+
async def test_template_helpers_do_not_log_argument_values(kernel: Kernel, caplog):
32+
secret = "SYNTHETIC_SECRET_VALUE"
33+
function = KernelFunctionFromMethod(kernel_function(lambda value: value, name="test"), plugin_name="test")
34+
sync_jinja_helper = create_template_helper_from_function(
35+
function, kernel, {}, JINJA2_TEMPLATE_FORMAT_NAME, enable_async=False
36+
)
37+
async_jinja_helper = create_template_helper_from_function(
38+
function, kernel, {}, JINJA2_TEMPLATE_FORMAT_NAME, enable_async=True
39+
)
40+
handlebars_helper = create_template_helper_from_function(
41+
function, kernel, {}, HANDLEBARS_TEMPLATE_FORMAT_NAME, enable_async=False
42+
)
43+
44+
caplog.set_level(logging.DEBUG, logger="semantic_kernel.prompt_template.utils.template_function_helpers")
45+
caplog.set_level(logging.DEBUG, logger="semantic_kernel.functions.kernel_function")
46+
sync_jinja_helper(value=secret)
47+
await async_jinja_helper(value=secret)
48+
handlebars_helper(secret, secret, value=secret)
49+
50+
all_messages = [
51+
record.getMessage()
52+
for record in caplog.records
53+
if record.name
54+
in {
55+
"semantic_kernel.prompt_template.utils.template_function_helpers",
56+
"semantic_kernel.functions.kernel_function",
57+
}
58+
]
59+
messages = [
60+
record.getMessage()
61+
for record in caplog.records
62+
if record.name == "semantic_kernel.prompt_template.utils.template_function_helpers"
63+
]
64+
assert secret not in "\n".join(all_messages)
65+
assert (
66+
messages.count("Invoking function test-test with positional argument count 0 and keyword argument count 1.")
67+
== 2
68+
)
69+
assert "Invoking function test-test with positional argument count 1 and keyword argument count 1." in messages
70+
assert "Handlebars context with `this`." in messages
71+
72+
2973
@pytest.mark.parametrize(
3074
"template_format, enable_async, exception",
3175
[

0 commit comments

Comments
 (0)