Produce function logs
Logs can help you understand how your function is used to prevent inappropriate behavior that causes any potential errors.
This document describes how to set log levels and produce logs for Pulsar functions.
Set log levels
A log level is a piece of information that indicates how important a given log message is. By default, the log level for Pulsar functions is info. If you want to check logs at different levels, you can configure the log levels for different Pulsar function runtimes.
You can use the spec.log.level option to specify a particular log level. Or, you can customize a log configuration file based on your requirements and reference to the log configuration file by using the spec.log.logConfig option.
This example shows how to specify a debug log level by using the spec.log.level option.
apiVersion: compute.functionmesh.io/v1alpha1
kind: Function
metadata:
name: function-sample
namespace: default
spec:
java: # --- [1]
log: # --- [2]
level: "debug" # --- [3]
- [1]
java: represents the runtime with a specific programming language. Currently, available options include the Java runtime, the Python runtime, and the Go runtime. - [2]
log: represents the log configurations for a Pulsar function. - [3]
level: represents the log levels available for a Pulsar function.
This example shows how to specify a debug log level by using the customized configuration file.
apiVersion: compute.functionmesh.io/v1alpha1
kind: Function
metadata:
name: function-sample
namespace: default
spec:
java: # --- [1]
log: # --- [2]
logConfig: # --- [3]
name: "java-log-config-cm"
key: "java-config-xml"
---
apiVersion: v1
kind: ConfigMap
metadata:
name: java-log-config-cm
data:
java-config-xml:
<Configuration>
<name>pulsar-functions-kubernetes-instance</name>
<monitorInterval>30</monitorInterval>
<Properties>
<Property> # --- [4]
<name>pulsar.log.level</name>
<value>DEBUG</value>
</Property>
<Property>
<name>bk.log.level</name>
<value>DEBUG</value>
</Property>
</Properties>
<Appenders> # --- [5]
<Console>
<name>Console</name>
<target>SYSTEM_OUT</target>
<PatternLayout>
<Pattern>%d{ISO8601_OFFSET_DATE_TIME_HHMM} [%t] %-5level %logger{36} - %msg%n</Pattern>
</PatternLayout>
</Console>
</Appenders>
<Loggers>
<Logger> # --- [6]
<name>org.apache.pulsar.functions.runtime.shaded.org.apache.bookkeeper</name>
<level>${sys:bk.log.level}</level>
<additivity>false</additivity> # --- [7]
<AppenderRef> # --- [8]
<ref>Console</ref>
</AppenderRef>
</Logger>
<Root>
<level>${sys:pulsar.log.level}</level>
<AppenderRef>
<ref>Console</ref>
<level>${sys:pulsar.log.level}</level>
</AppenderRef>
</Root>
</Loggers>
</Configuration>
- [1]
java: represents the runtime with a specific programming language. Currently, available options include the Java runtime, the Python runtime, and the Go runtime. - [2]
log: represents the log configurations for a Pulsar function. - [3]
logConfig: represents the log configuration file in a format of ConfigMap. - [4]
Property: it is a name-value pair that represents the log levels available for a Pulsar function. - [5]
Appenders: represents the destination that the logs are delivered to. - [6]
Loggers: represents a class or module type that is used to perform logging. - [7]
additivity: indicates whether log messages will be duplicated if multiple<Logger>entries overlap. If it is set tofalse, it means to prevent duplication of log messages when one or more<Logger>entries contain classes or modules that overlap. - [8]
AppenderRef: allows you to output the log to a destination that is specified in theAppenderssection.
Set log rotation policies
With more and more logs being written to the log file, the log file grows in size. Therefore, Function Mesh supports log rotation to avoid large files that could create issues when opening them. After being rotated, the original logs are compressed into a file and new logs are continuously written to the log file.
You can still access the log data within these compressed files, but you need to extract the file content to view it. Compressed files reduce their size and save disk space, and they take up less space when you archive or back up your logs to another location.
This example shows how to set the log rotation policy to TimedPolicyWithDaily by using the spec.<runtime>.log.rotatePolicy option.
apiVersion: compute.functionmesh.io/v1alpha1
kind: Function
metadata:
name: function-sample
namespace: default
spec:
java: # --- [1]
log: # --- [2]
rotatePolicy: "TimedPolicyWithDaily" # --- [3]
- [1]
java: represents the runtime with a specific programming language. Currently, available options include the Java runtime, the Python runtime, and the Go runtime. - [2]
log: represents the log configurations for a Pulsar function. - [3]
rotatePolicy: represents the log rotation policies available for a Pulsar function.
Produce logs for Pulsar functions
This section describes how to produce logs for Pulsar functions.
Produce logs for a Java function
To produce logs for a Java function, follow these steps.
Specify a log topic when you run a Java function.
This example specify the
persistent://public/default/logging-function-logsas the log topic for the Java function.apiVersion: compute.functionmesh.io/v1alpha1
kind: Function
metadata:
name: java-function-sample
namespace: default
spec:
image: streamnative/pulsar-functions-java-runner:2.7.1 # using java function runner
className: exclamation_function.ExclamationFunction
forwardSourceMessageProperty: true
maxPendingAsyncRequests: 1000
replicas: 1
maxReplicas: 5
logTopic: persistent://public/default/logging-function-logs
...Set a log level.
For details, see set log levels.
Apply the YAML file to run the Java function.
kubectl apply -f /path/to/YAML/fileAfter the Jave function runs successfully, you can check the log content, which is similar to:
2022-08-25T00:32:34,112+0000 [main] DEBUG io.grpc.netty.shaded.io.netty.channel.MultithreadEventLoopGroup - -Dio.netty.eventLoopThreads: 2
2022-08-25T00:32:35,012+0000 [main] DEBUG io.grpc.netty.shaded.io.netty.util.internal.InternalThreadLocalMap - -Dio.netty.threadLocalMap.stringBuilder.initialSize: 1024
2022-08-25T00:32:35,012+0000 [main] DEBUG io.grpc.netty.shaded.io.netty.util.internal.InternalThreadLocalMap - -Dio.netty.threadLocalMap.stringBuilder.maxSize: 4096
2022-08-25T00:32:35,115+0000 [main] DEBUG io.grpc.netty.shaded.io.netty.util.internal.PlatformDependent - org.jctools-core.MpscChunkedArrayQueue: available
2022-08-25T00:32:35,511+0000 [main] DEBUG io.grpc.netty.shaded.io.netty.util.ResourceLeakDetector - -Dio.grpc.netty.shaded.io.netty.leakDetection.level: simple
2022-08-25T00:32:35,512+0000 [main] DEBUG io.grpc.netty.shaded.io.netty.util.ResourceLeakDetector - -Dio.grpc.netty.shaded.io.netty.leakDetection.targetRecords: 4
2022-08-25T00:32:35,513+0000 [main] DEBUG io.grpc.netty.shaded.io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.numHeapArenas: 2
2022-08-25T00:32:35,513+0000 [main] DEBUG io.grpc.netty.shaded.io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.numDirectArenas: 2
2022-08-25T00:32:35,513+0000 [main] DEBUG io.grpc.netty.shaded.io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.pageSize: 8192
2022-08-25T00:32:35,513+0000 [main] DEBUG io.grpc.netty.shaded.io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.maxOrder: 11
2022-08-25T00:32:35,513+0000 [main] DEBUG io.grpc.netty.shaded.io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.chunkSize: 16777216
2022-08-25T00:32:35,513+0000 [main] DEBUG io.grpc.netty.shaded.io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.smallCacheSize: 256
2022-08-25T00:32:35,513+0000 [main] DEBUG io.grpc.netty.shaded.io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.normalCacheSize: 64
2022-08-25T00:32:35,514+0000 [main] DEBUG io.grpc.netty.shaded.io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.maxCachedBufferCapacity: 32768
2022-08-25T00:32:35,514+0000 [main] DEBUG io.grpc.netty.shaded.io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.cacheTrimInterval: 8192
2022-08-25T00:32:35,514+0000 [main] DEBUG io.grpc.netty.shaded.io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.cacheTrimIntervalMillis: 0
2022-08-25T00:32:35,514+0000 [main] DEBUG io.grpc.netty.shaded.io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.useCacheForAllThreads: true
2022-08-25T00:32:35,514+0000 [main] DEBUG io.grpc.netty.shaded.io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.maxCachedByteBuffersPerChunk: 1023
2022-08-25T00:32:35,815+0000 [grpc-default-boss-ELG-1-1] DEBUG io.grpc.netty.shaded.io.netty.channel.DefaultChannelId - -Dio.netty.processId: 1 (auto-detected)
2022-08-25T00:32:35,818+0000 [grpc-default-boss-ELG-1-1] DEBUG io.grpc.netty.shaded.io.netty.channel.DefaultChannelId - -Dio.netty.machineId: 5a:b8:c7:ff:fe:93:26:86 (auto-detected)
2022-08-25T00:32:36,215+0000 [grpc-default-boss-ELG-1-1] DEBUG io.grpc.netty.shaded.io.netty.buffer.ByteBufUtil - -Dio.netty.allocator.type: pooled
2022-08-25T00:32:36,215+0000 [grpc-default-boss-ELG-1-1] DEBUG io.grpc.netty.shaded.io.netty.buffer.ByteBufUtil - -Dio.netty.threadLocalDirectBufferSize: 0
2022-08-25T00:32:36,307+0000 [grpc-default-boss-ELG-1-1] DEBUG io.grpc.netty.shaded.io.netty.buffer.ByteBufUtil - -Dio.netty.maxThreadLocalCharBufferSize: 16384
2022-08-25T00:32:36,415+0000 [main] INFO org.apache.pulsar.functions.runtime.JavaInstanceStarter - JavaInstance Server started, listening on 9093
2022-08-25T00:32:36,416+0000 [main] INFO org.apache.pulsar.functions.runtime.JavaInstanceStarter - Starting runtimeSpawner
Produce logs for a Python function
To produce logs for a Python function, follow these steps.
Specify a log topic when you run a Python function.
This example specify the
persistent://public/default/logging-function-logsas the log topic for the Python function.apiVersion: compute.functionmesh.io/v1alpha1
kind: Function
metadata:
name: python-function-sample
namespace: default
spec:
image: streamnative/pulsar-functions-python-runner:2.7.1 # using python function runner
className: exclamation_function.ExclamationFunction
forwardSourceMessageProperty: true
maxPendingAsyncRequests: 1000
replicas: 1
maxReplicas: 5
logTopic: persistent://public/default/logging-function-logs
...Set a log level.
For details, see set log levels.
Apply the YAML file to run the Python function.
kubectl apply -f /path/to/YAML/fileAfter the Python function runs successfully, you can check the log content, which is similar to:
[2022-08-25 00:35:18 +0000] [INFO] python_instance_main.py: Starting Python instance with Namespace(client_auth_params=None, client_auth_plugin=None, cluster_name='test', dependency_repository=None, expected_healthcheck_interval=-1, extra_dependency_repository=None, function_details='{"tenant":"public","namesp
[2022-08-25 00:35:18 +0000] [DEBUG] util.py: Trying to import secretsprovider.EnvironmentBasedSecretsProvider from path /pulsar/instances/python-instance
[2022-08-25 00:35:18 +0000] [INFO] log.py: Setting up producer for log topic persistent://public/default/py-function-logs
2022-08-25 00:35:18.425 INFO [140709055104768] ExecutorService:41 | Run io_service in a single thread
2022-08-25 00:35:18.426 INFO [140709113706304] ClientConnection:189 | [<none> -> pulsar://sn-platform-pulsar-broker.default.svc.cluster.local:6650] Create ClientConnection, timeout=10000
2022-08-25 00:35:18.426 INFO [140709113706304] ConnectionPool:96 | Created connection for pulsar://sn-platform-pulsar-broker.default.svc.cluster.local:6650
2022-08-25 00:35:18.438 INFO [140709055104768] ClientConnection:375 | [10.233.106.150:37296 -> 10.233.106.118:6650] Connected to broker
2022-08-25 00:35:18.443 INFO [140709055104768] HandlerBase:64 | [persistent://public/default/py-function-logs, ] Getting connection from pool
2022-08-25 00:35:18.473 INFO [140709055104768] ClientConnection:189 | [<none> -> pulsar://sn-platform-pulsar-broker-0.sn-platform-pulsar-broker.default.svc.cluster.local:6650] Create ClientConnection, timeout=10000
2022-08-25 00:35:18.473 INFO [140709055104768] ConnectionPool:96 | Created connection for pulsar://sn-platform-pulsar-broker-0.sn-platform-pulsar-broker.default.svc.cluster.local:6650
2022-08-25 00:35:18.476 INFO [140709055104768] ClientConnection:375 | [10.233.106.150:37298 -> 10.233.106.118:6650] Connected to broker
2022-08-25 00:35:18.561 INFO [140709055104768] ProducerImpl:188 | [persistent://public/default/py-function-logs, ] Created producer on broker [10.233.106.150:37298 -> 10.233.106.118:6650]
[2022-08-25 00:35:18 +0000] [DEBUG] util.py: Trying to import serde.IdentitySerDe from path /pulsar/examples/python-examples
[2022-08-25 00:35:18 +0000] [DEBUG] util.py: Add a new dependency to the path: /pulsar/examples/python-examples
[2022-08-25 00:35:18 +0000] [DEBUG] util.py: Trying to import serde.IdentitySerDe from path /pulsar/instances/python-instance/pulsar/functions
[2022-08-25 00:35:18 +0000] [DEBUG] util.py: Add a new dependency to the path: /pulsar/instances/python-instance/pulsar/functions
[2022-08-25 00:35:18 +0000] [DEBUG] python_instance.py: Setting up consumer for topic persistent://public/default/input-python-log-level-topic with subname public/default/python-log-config
2022-08-25 00:35:18.568 INFO [140709113706304] Client:88 | Subscribing on Topic :persistent://public/default/input-python-log-level-topic
2022-08-25 00:35:18.601 INFO [140709055104768] HandlerBase:64 | [persistent://public/default/input-python-log-level-topic, public/default/python-log-config, 0] Getting connection from pool
2022-08-25 00:35:18.601 INFO [140708958693120] ExecutorService:41 | Run io_service in a single thread
2022-08-25 00:35:18.691 INFO [140709055104768] ConsumerImpl:222 | [persistent://public/default/input-python-log-level-topic, public/default/python-log-config, 0] Created consumer on broker [10.233.106.150:37298 -> 10.233.106.118:6650]
[2022-08-25 00:35:18 +0000] [DEBUG] util.py: Trying to import exclamation_function.ExclamationFunction from path /pulsar/examples/python-examples
[2022-08-25 00:35:18 +0000] [DEBUG] python_instance.py: Started Thread for executing the function
[2022-08-25 00:35:18 +0000] [INFO] server.py: Serving InstanceCommunication on port 9093