NginxModuleTraceAsError` directive not working as expected in ngx_http_opentelemetry_module

[mshafiee]

Describe your environment:

• Platform: Ubuntu 20.04.2 LTS
• Nginx Version: 1.26.0
• GCC Version: 9.4.0
• Kernel Version: Linux 6.5.0-1020-aws
• OpenTelemetry Module Version: Latest from the repository (webserver/v1.1.0)

Steps to reproduce:

1. Configure Nginx with the ngx_http_opentelemetry_module.
2. Set the NginxModuleTraceAsError directive to either ON or OFF in the Nginx configuration.
3. Start Nginx and observe the error logs.

What is the expected behavior?

• When NginxModuleTraceAsError is set to ON, trace logs should appear in the error logs.
• When NginxModuleTraceAsError is set to OFF, trace logs should not appear in the error logs.

What is the actual behavior?

• Regardless of whether NginxModuleTraceAsError is set to ON or OFF, trace logs are always written to the error logs.

Error Log:

nginx: [error] mod_opentelemetry: ngx_http_opentelemetry_init: Starting Opentelemetry Module init
nginx: [error] mod_opentelemetry: ngx_http_opentelemetry_init: Registering handlers for modules in different phases
nginx: [error] mod_opentelemetry: ngx_http_opentelemetry_init: Opentelemetry Module init completed!
2024/06/05 06:59:04 [notice] 1#1: using the "epoll" event method
2024/06/05 06:59:04 [notice] 1#1: nginx/1.26.0
2024/06/05 06:59:04 [notice] 1#1: built by gcc 9.4.0 (Ubuntu 9.4.0-1ubuntu1~20.04.2) 
2024/06/05 06:59:04 [notice] 1#1: OS: Linux 6.5.0-1020-aws
2024/06/05 06:59:04 [notice] 1#1: getrlimit(RLIMIT_NOFILE): 1048576:1048576
2024/06/05 06:59:04 [notice] 1#1: start worker processes
2024/06/05 06:59:04 [notice] 1#1: start worker process 27
2024/06/05 06:59:04 [notice] 1#1: start worker process 28
2024/06/05 06:59:04 [notice] 1#1: start cache manager process 29
2024/06/05 06:59:04 [notice] 1#1: start cache loader process 30
2024/06/05 06:59:04 [error] 27#27: mod_opentelemetry: ngx_http_opentelemetry_init_worker: Initializing Nginx Worker for process with PID: 27
2024/06/05 06:59:04 [error] 28#28: mod_opentelemetry: ngx_http_opentelemetry_init_worker: Initializing Nginx Worker for process with PID: 28
2024/06/05 06:59:04 [error] 29#29: mod_opentelemetry: ngx_http_opentelemetry_init_worker: Initializing Nginx Worker for process with PID: 29
2024/06/05 06:59:04 [error] 30#30: mod_opentelemetry: ngx_http_opentelemetry_init_worker: Initializing Nginx Worker for process with PID: 30
2024/06/05 07:00:33 [notice] 30#30: http file cache: /var/cache/contentful 136.043M, bsize: 512
2024/06/05 07:00:33 [notice] 1#1: signal 17 (SIGCHLD) received from 30
2024/06/05 07:00:33 [notice] 1#1: cache loader process 30 exited with code 0
2024/06/05 07:00:33 [notice] 1#1: signal 29 (SIGIO) received

Additional context:

• This issue causes unnecessary error logs and can make it difficult to distinguish actual errors from trace logs.
• The configuration directive NginxModuleTraceAsError does not seem to have any effect on the logging behavior.

[marcalff]

Thanks for the report.

The nginx module is part of the https://github.com/open-telemetry/opentelemetry-cpp-contrib repository, not https://github.com/open-telemetry/opentelemetry-cpp.

Migrating the issue to contrib.

[marcalff]

Root cause:

static ngx_int_t ngx_http_opentelemetry_init(ngx_conf_t *cf)
{
  ...
    ngx_writeError(cf->cycle->log, __func__, "Starting Opentelemetry Module init");

The issue is not with NginxModuleTraceAsError, but more like ngx_writeError() used instead of ngx_writeTrace().

[marcalff]

Related:

• nginx module logs debug info as errors #401