Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Closed
cexshun opened this issue Jul 9, 2024 · 7 comments · Fixed by #2317
Closed

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

cexshun opened this issue Jul 9, 2024 · 7 comments · Fixed by #2317
Labels
R-awaiting-answer
Milestone
4.23.0

Comments

@cexshun
Copy link

cexshun commented Jul 9, 2024

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 GitHub Actions
Copy link

github-actions bot commented Jul 9, 2024

@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
Copy link
Member

VietND96 commented Jul 9, 2024

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
Copy link
Author

cexshun commented Jul 9, 2024 •
edited
Loading

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
Copy link
Member

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
Copy link
Author

cexshun commented Jul 10, 2024 •
edited
Loading

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
Copy link
Member

diemol commented Jul 10, 2024

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

@VietND96 VietND96 mentioned this issue Jul 21, 2024
Merged
8 tasks
@VietND96 VietND96 added this to the 4.23.0 milestone Jul 21, 2024
@github-actions GitHub Actions
Copy link

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.

@github-actions github-actions bot locked and limited conversation to collaborators Aug 22, 2024
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
R-awaiting-answer
Projects
None yet
Milestone
4.23.0
Development

Successfully merging a pull request may close this issue.

add: Env var SE_SUPERVISORD_LOG_LEVEL to set supervisord log level NDViet/docker-selenium
3 participants
@diemol @cexshun @VietND96