[🐛 Bug]: NodeChrome ignores log level and floods INFO logs

[cexshun]

What happened?

Running Selenium on Kubernetes. We noticed our Datadog server is being flooded with node-chrome INFO logs. I have set the global logLevel to severe, but NodeChrome is still logging INFO. I've also attempted to set JAVA_OPTS, SE_JAVA_OPTS, and SE_OPTS environment labels using "-Dselenium.LOGGER.level=SEVERE" in NodeChrome with no effect. I've been unable to figure out how to reduce the log level of NodeChrome.

Command used to start Selenium Grid with Docker (or Kubernetes)

global:
  seleniumGrid:
    logLevel: SEVERE
autoscaling:
  # Enable autoscaling. Implies installing KEDA
  enabled: true

keda:
  metricsServer:
    dnsPolicy: ClusterFirstWithHostNet
    useHostNetwork: true
  logging:
    operator:
      level: error
    webhooks:
      level: error

ingress:
  className: "nginx"
  hostname: {{ env['selenium_fqdn'] }}

basicAuth:
  enabled: false

chromeNode:
  resources:
    requests:
      memory: "1Gi"
      cpu: "200m"
    limits:
      memory: "1Gi"
      cpu: "1"

  scaledOptions:
    # 2 sessions always immediately available
    minReplicaCount: 2
    maxReplicaCount: 16
  extraEnvironmentVariables:
    - name: SCREEN_WIDTH
      value: "1920"
    - name: SCREEN_HEIGHT
      value: "1080"
    - name: SE_VNC_NO_PASSWORD
      value: "1"
    - name: SE_NODE_SESSION_TIMEOUT
      value: "120"
    - name: JAVA_OPTS
      value: -Dselenium.LOGGER.level=SEVERE

firefoxNode:
  enabled: false

edgeNode:
  enabled: false

Relevant log output

Jul 09 10:28:04.537
i-011ce0bf9948708b9
node-chrome
Starting Selenium Grid Node...

Jul 09 10:28:04.537
i-011ce0bf9948708b9
node-chrome
2024-07-09 15:28:02,779 INFO success: xvfb entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)

Jul 09 10:28:04.537
i-011ce0bf9948708b9
node-chrome
2024-07-09 15:28:02,779 INFO success: vnc entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)

Jul 09 10:28:04.537
i-011ce0bf9948708b9
node-chrome
2024-07-09 15:28:02,779 INFO success: novnc entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)

Jul 09 10:28:14.536
i-011ce0bf9948708b9
node-chrome
2024-07-09 15:28:10,714 INFO Included extra file "/etc/supervisor/conf.d/chrome-cleanup.conf" during parsing

Jul 09 10:28:14.536
i-011ce0bf9948708b9
node-chrome
2024-07-09 15:28:10,714 INFO Included extra file "/etc/supervisor/conf.d/selenium.conf" during parsing

Jul 09 10:28:14.536
i-011ce0bf9948708b9
node-chrome
2024-07-09 15:28:10,717 INFO RPC interface 'supervisor' initialized

Jul 09 10:28:14.536
i-011ce0bf9948708b9
node-chrome
2024-07-09 15:28:10,717 CRIT Server 'unix_http_server' running without any HTTP authentication checking

Jul 09 10:28:14.536
i-011ce0bf9948708b9
node-chrome
2024-07-09 15:28:10,717 INFO supervisord started with pid 8

Jul 09 10:28:14.536
i-011ce0bf9948708b9
node-chrome
2024-07-09 15:28:11,719 INFO spawned: 'xvfb' with pid 9

Jul 09 10:28:14.536
i-011ce0bf9948708b9
node-chrome
2024-07-09 15:28:11,720 INFO spawned: 'vnc' with pid 10

Jul 09 10:28:14.536
i-011ce0bf9948708b9
node-chrome
2024-07-09 15:28:11,722 INFO spawned: 'novnc' with pid 11

Jul 09 10:28:14.536
i-011ce0bf9948708b9
node-chrome
2024-07-09 15:28:11,723 INFO spawned: 'selenium-node' with pid 12

Jul 09 10:28:14.536
i-011ce0bf9948708b9
node-chrome
2024-07-09 15:28:11,728 INFO success: selenium-node entered RUNNING state, process has stayed up for > than 0 seconds (startsecs)

Operating System

EKS

Docker Selenium version (image tag)

4.20.0-20240505

Selenium Grid chart version (chart version)

0.30.1

[github-actions]

@cexshun, thank you for creating this issue. We will troubleshoot it as soon as we can.

---

Info for maintainers

Triage this issue by using labels.

If information is missing, add a helpful comment and then I-issue-template label.

If the issue is a question, add the I-question label.

If the issue is valid but there is no time to troubleshoot it, consider adding the help wanted label.

If the issue requires changes or fixes from an external project (e.g., ChromeDriver, GeckoDriver, MSEdgeDriver, W3C), add the applicable G-* label, and it will provide the correct link and auto-close the issue.

After troubleshooting the issue, please add the R-awaiting answer label.

Thank you!

[VietND96]

From kubectl logs, do you see few lines for Appending Selenium options ?

2024-07-09 01:39:57,619 INFO Included extra file "/etc/supervisor/conf.d/chrome-cleanup.conf" during parsing
2024-07-09 01:39:57,619 INFO Included extra file "/etc/supervisor/conf.d/selenium.conf" during parsing
2024-07-09 01:39:57,629 INFO RPC interface 'supervisor' initialized
2024-07-09 01:39:57,629 CRIT Server 'unix_http_server' running without any HTTP authentication checking
2024-07-09 01:39:57,630 INFO supervisord started with pid 7
2024-07-09 01:39:58,632 INFO spawned: 'xvfb' with pid 8
2024-07-09 01:39:58,633 INFO spawned: 'vnc' with pid 9
2024-07-09 01:39:58,635 INFO spawned: 'novnc' with pid 10
2024-07-09 01:39:58,637 INFO spawned: 'selenium-node' with pid 11
2024-07-09 01:39:58,715 INFO success: selenium-node entered RUNNING state, process has stayed up for > than 0 seconds (startsecs)
Appending Selenium options: --session-timeout 300
Appending Selenium options: --enable-managed-downloads true
Appending Selenium options: --register-period 60
Appending Selenium options: --register-cycle 5
Appending Selenium options: --heartbeat-period 30
Appending Selenium options: --log-level FINE
Generating Selenium Config
Setting up SE_NODE_HOST...

[cexshun]

Yes I do.

Jul 09 10:28:14.536
i-011ce0bf9948708b9
node-chrome
Appending Selenium options: --register-period 60

Jul 09 10:28:14.536
i-011ce0bf9948708b9
node-chrome
Appending Selenium options: --register-cycle 5

Jul 09 10:28:14.536
i-011ce0bf9948708b9
node-chrome
Appending Selenium options: --heartbeat-period 30

Jul 09 10:28:14.536
i-011ce0bf9948708b9
node-chrome
Appending Selenium options: --log-level SEVERE

Jul 09 10:28:14.536
i-011ce0bf9948708b9
node-chrome
Generating Selenium Config

[VietND96]

Within --log-level, I think the log level is set to node correctly.
By using kubectl logs can you share all output from a node pod after few test runs. I want to see how many it looks like

[cexshun]

Not seeing any logs starting or during the tests.

2024-07-10 18:50:46,635 INFO Included extra file "/etc/supervisor/conf.d/selenium.conf" during parsing
2024-07-10 18:50:46,638 INFO RPC interface 'supervisor' initialized
2024-07-10 18:50:46,638 CRIT Server 'unix_http_server' running without any HTTP authentication checking
2024-07-10 18:50:46,638 INFO supervisord started with pid 8
2024-07-10 18:50:47,640 INFO spawned: 'xvfb' with pid 9
2024-07-10 18:50:47,641 INFO spawned: 'vnc' with pid 10
2024-07-10 18:50:47,643 INFO spawned: 'novnc' with pid 11
2024-07-10 18:50:47,644 INFO spawned: 'selenium-node' with pid 12
2024-07-10 18:50:47,649 INFO success: selenium-node entered RUNNING state, process has stayed up for > than 0 seconds (startsecs)
Appending Selenium options: --session-timeout 120
Appending Selenium options: --register-period 60
Appending Selenium options: --register-cycle 5
Appending Selenium options: --heartbeat-period 30
Appending Selenium options: --log-level SEVERE
Generating Selenium Config
Setting up SE_NODE_HOST...
Tracing is disabled
Selenium Grid Node configuration: 
[events]
publish = "tcp://redacted:4442"
subscribe = "tcp://redacted:4443"

[server]
port = "5555"
[node]
grid-url = "redacted"
session-timeout = "120"
override-max-sessions = false
detect-drivers = false
drain-after-session-count = 1
max-sessions = 1

[[node.driver-configuration]]
display-name = "chrome"
stereotype = '{"browserName": "chrome", "browserVersion": "124.0", "platformName": "Linux", "goog:chromeOptions": {"binary": "/usr/bin/google-chrome"}}'
max-sessions = 1

Starting Selenium Grid Node...
2024-07-10 18:50:48,665 INFO success: xvfb entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2024-07-10 18:50:48,665 INFO success: vnc entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2024-07-10 18:50:48,665 INFO success: novnc entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)```

So where are the INFO logs coming from? It would appear once it starts, the logs go silent. But start up is chatting, even not counting all of the node-startup debug echos.

[diemol]

Logs are coming from supervisor, which get sent to stdout when the container runs.

[github-actions]

This issue has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.