Project

General

Profile

Actions
Copy link

action #14904

closed

log warn message: Can't call method "DISTRI" on an undefined value

Added by okurz over 7 years ago. Updated over 4 years ago.

Status:
Resolved
Priority:
Low
Assignee:
mkittler
Category:
Regressions/Crashes
Target version:
Done
Start date:
2016-11-20
Due date:
% Done:

0%

Estimated time:

Description

observation

Error in logfile on o3:

From /var/log/openqa:

[Wed Nov 16 13:35:52 2016] [31812:debug] [DBIx debug] Took 0.00031304 seconds executed: SELECT me.id, me.name, me.default_size_limit_gb, me.default_keep_logs_in_days, me.default_keep_important_logs_in_days, me.default_keep_results_in_days, me.default_keep_important_results_in_days, me.default_priority, me.sort_order, me.description, me.t_created, me.t_updated FROM job_group_parents me ORDER BY sort_order ASC, name ASC: .
[Wed Nov 16 13:35:52 2016] [31812:debug] [DBIx debug] Took 0.00019312 seconds executed: SELECT me.id, me.name, me.parent_id, me.size_limit_gb, me.keep_logs_in_days, me.keep_important_logs_in_days, me.keep_results_in_days, me.keep_important_results_in_days, me.default_priority, me.sort_order, me.description, me.t_created, me.t_updated FROM job_groups me WHERE ( parent_id IS NULL ) ORDER BY sort_order ASC, name ASC: .
[Wed Nov 16 13:35:52 2016] [31812:debug] POST "/api/v1/jobs/306005/status"
[Wed Nov 16 13:35:52 2016] [31812:debug] Routing to controller "OpenQA::WebAPI::Controller::API::V1" and action "auth_operator"
[Wed Nov 16 13:35:52 2016] [31812:debug] API key from client: *5D46836035B1FE08*
[Wed Nov 16 13:35:52 2016] [31812:debug] [DBIx debug] Took 0.00024319 seconds executed: SELECT me.id, me.key, me.secret, me.user_id, me.t_expiration, me.t_created, me.t_updated FROM api_keys me WHERE ( me.key = ? ): '5D46836035B1FE08'.
[Wed Nov 16 13:35:52 2016] [31812:debug] [DBIx debug] Took 0.00022697 seconds executed: SELECT me.id, me.username, me.email, me.fullname, me.nickname, me.is_operator, me.is_admin, me.t_created, me.t_updated FROM users me WHERE ( me.id = ? ): '66'.
[Wed Nov 16 13:35:52 2016] [31812:debug] Key is for user 'https://www.opensuse.org/openid/user/k0da'
[Wed Nov 16 13:35:52 2016] [31812:debug] API auth by user: https://www.opensuse.org/openid/user/k0da, operator: 1
[Wed Nov 16 13:35:52 2016] [31812:debug] Routing to controller "OpenQA::WebAPI::Controller::API::V1::Job" and action "update_status"
[Wed Nov 16 13:35:52 2016] [31812:debug] [DBIx debug] Took 0.00018597 seconds executed: SELECT me.id, me.slug, me.result_dir, me.state, me.priority, me.result, me.clone_id, me.retry_avbl, me.backend, me.backend_info, me.TEST, me.DISTRI, me.VERSION, me.FLAVOR, me.ARCH, me.BUILD, me.MACHINE, me.group_id, me.t_started, me.t_finished, me.t_created, me.t_updated FROM jobs me WHERE ( me.id = ? ): '306005'.
[Wed Nov 16 13:35:52 2016] [31812:debug] [DBIx debug] Took 0.00015616 seconds executed: SELECT me.id, me.host, me.instance, me.job_id, me.t_created, me.t_updated FROM workers me WHERE ( me.job_id = ? ): '306005'.
[Wed Nov 16 13:35:52 2016] [31812:debug] [DBIx debug] Took 0.00020003 seconds executed: SELECT me.id, me.job_id, me.name, me.script, me.category, me.milestone, me.important, me.fatal, me.result, me.t_created, me.t_updated FROM job_modules me WHERE ( ( me.job_id = ? AND me.name = ? ) ): '306005', 'chromium'.
[Wed Nov 16 13:35:52 2016] [31812:debug] [DBIx debug] Took 0.00014091 seconds executed: DELETE FROM job_module_needles WHERE ( job_module_id = ? ): '7035959'.
[Wed Nov 16 13:35:52 2016] [31812:debug] [DBIx debug] Took 0.00017190 seconds executed: SELECT me.id, me.slug, me.result_dir, me.state, me.priority, me.result, me.clone_id, me.retry_avbl, me.backend, me.backend_info, me.TEST, me.DISTRI, me.VERSION, me.FLAVOR, me.ARCH, me.BUILD, me.MACHINE, me.group_id, me.t_started, me.t_finished, me.t_created, me.t_updated FROM jobs me WHERE ( me.id = ? ): '306005'.
[Wed Nov 16 13:35:52 2016] [31849:debug] [DBIx debug] Took 0.00040507 seconds executed: SELECT me.id, me.name, me.default_size_limit_gb, me.default_keep_logs_in_days, me.default_keep_important_logs_in_days, me.default_keep_results_in_days, me.default_keep_important_results_in_days, me.default_priority, me.sort_order, me.description, me.t_created, me.t_updated FROM job_group_parents me ORDER BY sort_order ASC, name ASC: .
[Wed Nov 16 13:35:52 2016] [31849:debug] [DBIx debug] Took 0.00014591 seconds executed: SELECT me.id, me.name, me.parent_id, me.size_limit_gb, me.keep_logs_in_days, me.keep_important_logs_in_days, me.keep_results_in_days, me.keep_important_results_in_days, me.default_priority, me.sort_order, me.description, me.t_created, me.t_updated FROM job_groups me WHERE ( parent_id IS NULL ) ORDER BY sort_order ASC, name ASC: .
[Wed Nov 16 13:35:52 2016] [31849:debug] GET "/tests/277246/modules/user_settings/steps/1/src"
[Wed Nov 16 13:35:52 2016] [31812:debug] [DBIx debug] Took 0.00020504 seconds executed: SELECT me.id, me.key, me.value, me.worker_id, me.t_created, me.t_updated FROM worker_properties me WHERE ( ( me.key = ? AND me.worker_id = ? ) ): 'INTERACTIVE', '53'.
[Wed Nov 16 13:35:52 2016] [31812:debug] [DBIx debug] Took 0.00297594 seconds executed: UPDATE workers SET t_updated = ? WHERE ( id = ? ): '2016-11-16 12:35:52', '53'.
[Wed Nov 16 13:35:52 2016] [31812:debug] BEGIN WORK
[Wed Nov 16 13:35:52 2016] [31812:debug] COMMIT
[Wed Nov 16 13:35:52 2016] [31812:debug] [DBIx debug] Took 0.00041413 seconds executed: SELECT me.id, me.job_id, me.name, me.script, me.category, me.milestone, me.important, me.fatal, me.result, me.t_created, me.t_updated FROM job_modules me WHERE ( me.job_id = ? ): '306005'.
[Wed Nov 16 13:35:52 2016] [31812:debug] 200 OK (0.027929s, 35.805/s)
[Wed Nov 16 13:35:52 2016] [31849:debug] Routing to controller "OpenQA::WebAPI::Controller::Step" and action "src"
[Wed Nov 16 13:35:52 2016] [31849:debug] [DBIx debug] Took 0.02365494 seconds executed: SELECT me.id, me.slug, me.result_dir, me.state, me.priority, me.result, me.clone_id, me.retry_avbl, me.backend, me.backend_info, me.TEST, me.DISTRI, me.VERSION, me.FLAVOR, me.ARCH, me.BUILD, me.MACHINE, me.group_id, me.t_started, me.t_finished, me.t_created, me.t_updated FROM jobs me WHERE ( me.id = ? ): '277246'.
[Wed Nov 16 13:35:52 2016] [31849:debug] Template "not_found.production.html.ep" not found
[Wed Nov 16 13:35:52 2016] [31849:debug] Rendering cached template "not_found.html.ep"
[Wed Nov 16 13:35:52 2016] [31849:debug] Rendering cached template "layouts/error.html.ep"
[Wed Nov 16 13:35:52 2016] [31849:debug] 404 Not Found (0.045139s, 22.154/s)
[Wed Nov 16 13:35:52 2016] [31849:error] Can't call method "DISTRI" on an undefined value at /usr/share/openqa/script/../lib/OpenQA/WebAPI/Controller/Step.pm line 360.

[Wed Nov 16 13:35:52 2016] [31849:debug] Template "exception.production.html.ep" not found
[Wed Nov 16 13:35:52 2016] [31849:debug] Rendering template "exception.html.ep"
[Wed Nov 16 13:35:52 2016] [31849:debug] Rendering cached template "layouts/error.html.ep"

From /var/log/apache2/access_log:

192.168.112.6 - - [16/Nov/2016:13:35:52 +0100] "POST /api/v1/jobs/306005/status HTTP/1.1" 200 52 "-" "Mojolicious (Perl)"
192.168.254.4 - - [16/Nov/2016:13:35:52 +0100] "GET /tests/277246/modules/user_settings/steps/1/src HTTP/1.1" 500 2401 "-" "ltx71 - (http://ltx71.com/)"
192.168.112.7 - - [16/Nov/2016:13:35:52 +0100] "POST /api/v1/jobs/306028/artefact HTTP/1.1" 404 33333 "-" "Mojolicious (Perl)"
192.168.112.7 - - [16/Nov/2016:13:35:52 +0100] "POST /api/v1/jobs/306028/artefact HTTP/1.1" 404 33333 "-" "Mojolicious (Perl)"
192.168.112.3 - - [16/Nov/2016:13:35:52 +0100] "POST /api/v1/jobs/306012/status HTTP/1.1" 200 52 "-" "Mojolicious (Perl)"
192.168.112.7 - - [16/Nov/2016:13:35:52 +0100] "POST /api/v1/jobs/306028/artefact HTTP/1.1" 404 33333 "-" "Mojolicious (Perl)"
192.168.112.7 - - [16/Nov/2016:13:35:52 +0100] "POST /api/v1/jobs/306028/artefact HTTP/1.1" 404 33333 "-" "Mojolicious (Perl)"
192.168.112.7 - - [16/Nov/2016:13:35:52 +0100] "POST /api/v1/jobs/306028/artefact HTTP/1.1" 404 33333 "-" "Mojolicious (Perl)"
192.168.112.7 - - [16/Nov/2016:13:35:52 +0100] "POST /api/v1/jobs/306028/artefact HTTP/1.1" 404 33333 "-" "Mojolicious (Perl)"
192.168.112.6 - - [16/Nov/2016:13:35:52 +0100] "POST /api/v1/jobs/306005/status HTTP/1.1" 200 52 "-" "Mojolicious (Perl)"
192.168.112.7 - - [16/Nov/2016:13:35:52 +0100] "POST /api/v1/jobs/306028/artefact HTTP/1.1" 404 33333 "-" "Mojolicious (Perl)"
192.168.112.7 - - [16/Nov/2016:13:35:52 +0100] "POST /api/v1/jobs/306028/artefact HTTP/1.1" 404 33333 "-" "Mojolicious (Perl)"
192.168.112.6 - - [16/Nov/2016:13:35:52 +0100] "POST /api/v1/jobs/305957/status HTTP/1.1" 200 52 "-" "Mojolicious (Perl)"
192.168.112.7 - - [16/Nov/2016:13:35:52 +0100] "POST /api/v1/jobs/306028/artefact HTTP/1.1" 404 33333 "-" "Mojolicious (Perl)"
192.168.112.1 - - [16/Nov/2016:13:35:52 +0100] "POST /api/v1/jobs/306033/status HTTP/1.1" 200 52 "-" "Mojolicious (Perl)"
192.168.112.7 - - [16/Nov/2016:13:35:52 +0100] "POST /api/v1/jobs/306028/artefact HTTP/1.1" 404 33333 "-" "Mojolicious (Perl)"
192.168.112.7 - - [16/Nov/2016:13:35:52 +0100] "POST /api/v1/jobs/306032/status HTTP/1.1" 200 52 "-" "Mojolicious (Perl)"
192.168.112.7 - - [16/Nov/2016:13:35:52 +0100] "POST /api/v1/jobs/306028/artefact HTTP/1.1" 404 33333 "-" "Mojolicious (Perl)"
192.168.112.7 - - [16/Nov/2016:13:35:52 +0100] "POST /api/v1/jobs/306028/artefact HTTP/1.1" 404 33333 "-" "Mojolicious (Perl)"

No errors in /var/log/apache2/error_log at this time.

The error repeats multiple times a day.

Actions
Copy link
 #1

Updated by okurz over 7 years ago

  • Private changed from Yes to No
Actions
Copy link
 #2

Updated by coolo over 7 years ago

  • Priority changed from Normal to Low

these are spiders crawling dead jobs - we shouldn't crash on it, but return correctly 404. But we have more urgent issues

Actions
Copy link
 #3

Updated by coolo over 6 years ago

  • Target version set to Ready

possibly already fixed - as okurz didn't ping this issue monthly :)

Actions
Copy link
 #4

Updated by okurz over 6 years ago

Why should I ping?

Not fixed. From o3:

grep 'method.*DISTRI' /var/log/openqa | wc -l

399

Actions
Copy link
 #5

Updated by coolo over 6 years ago

To note: this log starts aug 16, so it's 3 months.

But we see them in bursts, because of:

[01/Nov/2017:02:32:36 +0000] "GET /tests/118466/modules/sshd/steps/10/src HTTP/1.1" 500 2401 "-" "YisouSpider"
[04/Nov/2017:01:01:47 +0000] "GET /tests/466936/modules/start_install/steps/1/src HTTP/1.1" 500 2401 "-" "ltx71 - (http://ltx71.com/)"
[04/Nov/2017:03:28:09 +0000] "GET /tests/467482/modules/bootloader/steps/1/src HTTP/1.1" 500 2401 "-" "ltx71 - (http://ltx71.com/)"
[04/Nov/2017:05:35:58 +0000] "GET /tests/466936/modules/installation_overview/steps/1/src HTTP/1.1" 500 2401 "-" "ltx71 - (http://ltx71.com/)"
[04/Nov/2017:08:34:27 +0000] "GET /tests/466936/modules/installer_timezone/steps/1/src HTTP/1.1" 500 2401 "-" "ltx71 - (http://ltx71.com/)"
[04/Nov/2017:22:55:39 +0000] "GET /tests/467482/modules/hexchat/steps/1/src HTTP/1.1" 500 2401 "-" "ltx71 - (http://ltx71.com/)"
[05/Nov/2017:08:20:32 +0000] "GET /tests/467482/modules/zypper_ar/steps/1/src HTTP/1.1" 500 2401 "-" "ltx71 - (http://ltx71.com/)"
[05/Nov/2017:19:07:34 +0000] "GET /tests/467625/modules/partitioning/steps/1/src HTTP/1.1" 500 2401 "-" "ltx71 - (http://ltx71.com/)"
[06/Nov/2017:13:58:32 +0000] "GET /tests/467482/modules/khelpcenter/steps/1/src HTTP/1.1" 500 2401 "-" "ltx71 - (http://ltx71.com/)"
[08/Nov/2017:00:13:02 +0000] "GET /tests/467482/modules/grub_test/steps/1/src HTTP/1.1" 500 2401 "-" "ltx71 - (http://ltx71.com/)"
[08/Nov/2017:15:17:42 +0000] "GET /tests/471211/modules/installation_mode/steps/1/src HTTP/1.1" 500 2401 "-" "ltx71 - (http://ltx71.com/)"

Basically bots ignoring robots.txt

Actions
Copy link
 #6

Updated by coolo over 5 years ago

  • Difficulty set to easy
Actions
Copy link
 #7

Updated by mkittler over 5 years ago

  • Status changed from New to In Progress
  • Assignee set to mkittler
Actions
Copy link
 #9

Updated by mkittler over 5 years ago

  • Status changed from In Progress to Resolved

PR has been merged

Actions
Copy link
 #10

Updated by coolo over 4 years ago

  • Target version changed from Ready to Done
Actions
Copy link

Also available in: Atom PDF