The Puppet Labs Issue Tracker has Moved: https://tickets.puppetlabs.com

This issue tracker is now in read-only archive mode and automatic ticket export has been disabled. Redmine users will need to create a new JIRA account to file tickets using https://tickets.puppetlabs.com. See the following page for information on filing tickets with JIRA:

Bug #18411

Delayed jobs problems since upgrade to 1.2.17

Added by Julien Cornuwel over 3 years ago. Updated over 2 years ago.

Status:AcceptedStart date:
Priority:NormalDue date:
Assignee:Aaron Stone% Done:

0%

Category:-
Target version:-
Keywords: Affected URL:
Branch: Affected Dashboard version:1.2.17

Description

Hi,

I have a Puppetmaster/Dashboard server running on Debian (installed from puppetlabs repositories). Since the upgrade to 1.2.17, I noticed the delayed jobs had become very slow. I configured it to spawn 10 workers and it is currently chewing at past reports (still 3000 pending).

Looking at the logfile, it seems like the delayed_jobs choke on some SQL inserts (logfile attached).

Regards,

delayed_job.log (955 KB) Julien Cornuwel, 01/08/2013 06:41 am


Related issues

Related to Puppet - Bug #20479: Puppet reports can contain invalid data that break puppet... Needs Decision

History

#1 Updated by Aaron Stone over 3 years ago

What version of Dashboard were you coming from?

What encoding your database is in — utf8 or latin-1?

#2 Updated by Aaron Stone over 3 years ago

Your error is in one INSERT statement for one specific YAML file, and it’s related to a string that either isn’t being escaped properly or is in an invalid encoding for your database:

Report.create_from_yaml_file failed with ActiveRecord::StatementInvalid: Mysql::Error: Incorrect string value: ‘\xE9chou\xE9…’ for column ‘details’ at row 1: INSERT INTO delayed_job_failures (created_at, details, updated_at, read, summary, backtrace) VALUES(‘2013-01-08 14:27:46’, ‘Mysql::Error: Incorrect string value: \’\xE9chou\xE9…\‘ for column \'message\’ at row 1: INSERT INTO report_logs (line, level, time, tags, report_id, file, message, source) VALUES(NULL, \‘err\’, \‘2013-01-07 15:29:10\’, \‘—– \n- err\n- file\n- plugin\n\’, 661045, NULL, \‘Failed to generate additional resources using \\'eval_generate: Une tentative de connexion a �chou� car le parti connect� n\\'a pas r�pondu convenablement au-del� d\\'une certaine dur�e ou une connexion �tablie a �chou� car l\\'h�te de connexion n\\'a pas r�pondu. – connect(2)\’, \‘/File[C:/Documents and Settings/All Users/Application Data/PuppetLabs/puppet/var/lib]\’)‘, '2013-01-08 14:27:46’, 0, ‘Importing report report-32531-217.yaml’,

#3 Updated by Julien Cornuwel over 3 years ago

And reading the backlog, it seems it only happens with Windows hosts, which are all running Puppet 2.7.14

I’m not exactly sure when the problem started, but here is the upgrade path I followed:

Aptitude 0.6.3: log report
Tue, Jan  8 2013 14:54:32 +0100
[UPGRADE] puppet-dashboard 1.2.16-1puppetlabs1 -> 1.2.17-1puppetlabs1
Aptitude 0.6.3: log report
Mon, Dec 31 2012 12:03:36 +0100
[UPGRADE] puppet-dashboard 1.2.14-1puppetlabs1 -> 1.2.16-1puppetlabs1

And the database encoding is UTF8:

mysql> use dashboard
mysql> show variables like "character_set_database";
+------------------------+-------+
| Variable_name          | Value |
+------------------------+-------+
| character_set_database | utf8  |
+------------------------+-------+
1 row in set (0.00 sec)

#4 Updated by Julien Cornuwel over 3 years ago

Oh, and BTW, I didn’t realize it was only one report that was triggering the problem. Thank you for that! I deleted it and everything is back to normal, almost…

Although the workers are processing reports as they come now, the interface still shows 45 pending tasks and the number doesn’t go down. I tried restarting the workers but they are still there. Any way to flush these?

#5 Updated by Aaron Stone over 3 years ago

Awesome, glad most of the issue is cleared!

2.7.14 is pretty old on the nodes, I’d need you to be running the latest version to see if the problem is still there.

About the old jobs, I’m not sure. That’s a bit of delayed_job that I’m not yet familiar with!

#6 Updated by Kiril Varnakov over 3 years ago

My log:

2013-01-10T16:46:21+0400: [Worker(delayed_job.1 host:hostname pid:13494)] Report.create_from_yaml_file failed with ActiveRecord::StatementInvalid: Mysql::Error: Incorrect string value: ‘\xDF_18.…’ for column ‘details’ at row 1: INSERT INTO delayed_job_failures (created_at, summary, updated_at, read, backtrace, details) VALUES(‘2013-01-10 12:46:21’, ‘Importing report report-56030-8.yaml’, ‘2013-01-10 12:46:21’, 0, ‘—– \n- /usr/local/share/puppet-dashboard/vendor/rails/activerecord/lib/active_record/connection_adapters/abstract_adapter.rb:227:in log\'\n- /usr/local/share/puppet-dashboard/vendor/rails/activerecord/lib/active_record/connection_adapters/mysql_adapter.rb:324:inexecute\’\n- /usr/local/share/puppet-dashboard/vendor/rails/activerecord/lib/active_record/connection_adapters/abstract/database_statements.rb:259:in insert_sql\'\n- /usr/local/share/puppet-dashboard/vendor/rails/activerecord/lib/active_record/connection_adapters/mysql_adapter.rb:334:ininsert_sql\‘\n- /usr/local/share/puppet-dashboard/vendor/rails/activerecord/lib/active_record/connection_adapters/abstract/database_statements.rb:44:in insert_without_query_dirty\'\n- /usr/local/share/puppet-dashboard/vendor/rails/activerecord/lib/active_record/connection_adapters/abstract/query_cache.rb:19:ininsert\’\n- /usr/local/share/puppet-dashboard/vendor/rails/activerecord/lib/active_record/base.rb:2967:in create_without_timestamps\'\n- /usr/local/share/puppet-dashboard/vendor/rails/activerecord/lib/active_record/timestamp.rb:53:increate_without_callbacks\‘\n- /usr/local/share/puppet-dashboard/vendor/rails/activerecord/lib/active_record/callbacks.rb:266:in create\'\n- /usr/local/share/puppet-dashboard/vendor/rails/activerecord/lib/active_record/base.rb:2933:increate_or_update_without_callbacks\’\n- /usr/local/share/puppet-dashboard/vendor/rails/activerecord/lib/active_record/callbacks.rb:250:in create_or_update\'\n- /usr/local/share/puppet-dashboard/vendor/rails/activerecord/lib/active_record/base.rb:2583:insave_without_validation\‘\n- /usr/local/share/puppet-dashboard/vendor/rails/activerecord/lib/active_record/validations.rb:1089:in save_without_dirty\'\n- /usr/local/share/puppet-dashboard/vendor/rails/activerecord/lib/active_record/dirty.rb:79:insave_without_transactions\’\n- /usr/local/share/puppet-dashboard/vendor/rails/activerecord/lib/active_record/transactions.rb:229:in send\'\n- /usr/local/share/puppet-dashboard/vendor/rails/activerecord/lib/active_record/transactions.rb:229:inwith_transaction_returning_status\‘\n- /usr/local/share/puppet-dashboard/vendor/rails/activerecord/lib/active_record/connection_adapters/abstract/database_statements.rb:136:in transaction\'\n- /usr/local/share/puppet-dashboard/vendor/rails/activerecord/lib/active_record/transactions.rb:182:intransaction\’\n- /usr/local/share/puppet-dashboard/vendor/rails/activerecord/lib/active_record/transactions.rb:228:in with_transaction_returning_status\'\n- /usr/local/share/puppet-dashboard/vendor/rails/activerecord/lib/active_record/transactions.rb:196:insave\‘\n- /usr/local/share/puppet-dashboard/vendor/rails/activerecord/lib/active_record/transactions.rb:208:in rollback_active_record_state!\'\n- /usr/local/share/puppet-dashboard/vendor/rails/activerecord/lib/active_record/transactions.rb:196:insave\’\n- /usr/local/share/puppet-dashboard/vendor/rails/activerecord/lib/active_record/associations/has_many_association.rb:61:in insert_record\'\n- /usr/local/share/puppet-dashboard/vendor/rails/activerecord/lib/active_record/associations/association_proxy.rb:146:insend\‘\n- /usr/local/share/puppet-dashboard/vendor/rails/activerecord/lib/active_record/associations/association_proxy.rb:146:in send\'\n- /usr/local/share/puppet-dashboard/vendor/rails/activerecord/lib/active_record/autosave_association.rb:321:insave_collection_association\’\n- /usr/local/share/puppet-dashboard/vendor/gems/will_paginate-2.3.15/lib/will_paginate/finder.rb:168:in method_missing\'\n- /usr/local/share/puppet-dashboard/vendor/rails/activerecord/lib/active_record/associations/association_collection.rb:392:inmethod_missing_without_paginate\‘\n- /usr/local/share/puppet-dashboard/vendor/rails/activerecord/lib/active_record/associations/association_proxy.rb:215:in each\'\n- /usr/local/share/puppet-dashboard/vendor/rails/activerecord/lib/active_record/associations/association_proxy.rb:215:insend\’\n- /usr/local/share/puppet-dashboard/vendor/rails/activerecord/lib/active_record/associations/association_proxy.rb:215:in method_missing\'\n- /usr/local/share/puppet-dashboard/vendor/rails/activerecord/lib/active_record/associations/association_collection.rb:392:inmethod_missing_without_paginate\‘\n- /usr/local/share/puppet-dashboard/vendor/gems/will_paginate-2.3.15/lib/will_paginate/finder.rb:168:in method_missing\'\n- /usr/local/share/puppet-dashboard/vendor/rails/activerecord/lib/active_record/autosave_association.rb:314:insave_collection_association\’\n- /usr/local/share/puppet-dashboard/vendor/rails/activerecord/lib/active_record/autosave_association.rb:176:in autosave_associated_records_for_resource_statuses\'\n- /usr/local/share/puppet-dashboard/vendor/rails/activesupport/lib/active_support/callbacks.rb:178:insend\‘\n- /usr/local/share/puppet-dashboard/vendor/rails/activesupport/lib/active_support/callbacks.rb:178:in evaluate_method\'\n- /usr/local/share/puppet-dashboard/vendor/rails/activesupport/lib/active_support/callbacks.rb:166:incall\’\n- /usr/local/share/puppet-dashboard/vendor/rails/activesupport/lib/active_support/callbacks.rb:93:in run\'\n- /usr/local/share/puppet-dashboard/vendor/rails/activesupport/lib/active_support/callbacks.rb:92:ineach\‘\n- /usr/local/share/puppet-dashboard/vendor/rails/activesupport/lib/active_support/callbacks.rb:92:in send\'\n- /usr/local/share/puppet-dashboard/vendor/rails/activesupport/lib/active_support/callbacks.rb:92:inrun\’\n- /usr/local/share/puppet-dashboard/vendor/rails/activesupport/lib/active_support/callbacks.rb:276:in run_callbacks\'\n- /usr/local/share/puppet-dashboard/vendor/rails/activerecord/lib/active_record/callbacks.rb:344:incallback\‘\n- /usr/local/share/puppet-dashboard/vendor/rails/activerecord/lib/active_record/callbacks.rb:267:in create\'\n- /usr/local/share/puppet-dashboard/vendor/rails/activerecord/lib/active_record/base.rb:2933:increate_or_update_without_callbacks\’\n- /usr/local/share/puppet-dashboard/vendor/rails/activerecord/lib/active_record/callbacks.rb:250:in create_or_update\'\n- /usr/local/share/puppet-dashboard/vendor/rails/activerecord/lib/active_record/base.rb:2600:insave_without_validation!\‘\n- /usr/local/share/puppet-dashboard/vendor/rails/activerecord/lib/active_record/validations.rb:1099:in save_without_dirty!\'\n- /usr/local/share/puppet-dashboard/vendor/rails/activerecord/lib/active_record/dirty.rb:87:insave_without_transactions!\’\n- /usr/local/share/puppet-dashboard/vendor/rails/activerecord/lib/active_record/transactions.rb:200:in save!\'\n- /usr/local/share/puppet-dashboard/vendor/rails/activerecord/lib/active_record/connection_adapters/abstract/database_statements.rb:136:intransaction\‘\n- /usr/local/share/puppet-dashboard/vendor/rails/activerecord/lib/active_record/transactions.rb:182:in transaction\'\n- /usr/local/share/puppet-dashboard/vendor/rails/activerecord/lib/active_record/transactions.rb:200:insave!\’\n- /usr/local/share/puppet-dashboard/vendor/rails/activerecord/lib/active_record/transactions.rb:208:in rollback_active_record_state!\'\n- /usr/local/share/puppet-dashboard/vendor/rails/activerecord/lib/active_record/transactions.rb:200:insave!\‘\n- /usr/local/share/puppet-dashboard/app/models/report.rb:117:in create_from_yaml\'\n- /usr/local/share/puppet-dashboard/app/models/report.rb:90:increate_from_yaml_file\’\n', ‘Mysql::Error: Incorrect string value: \’\xDF_18.…\‘ for column \'title\’ at row 1: INSERT INTO resource_statuses (resource_type, line, title, out_of_sync_count, time, change_count, failed, report_id, evaluation_time, tags, file, skipped, status) VALUES(\‘File\’, NULL, \‘/home/www-servers/hostname/html/help/pro/NP_Proъ18._07.2011_popup_text.js\’, 0, \‘2013-01-10 11:07:46\’, 0, 0, 645051, 0.00172, \‘—– \n- file\n- nginx_files_hostname\n- nginx::files::nginx_files_hosts\n- nginx\n- files\n- nginx_files_hosts\n- hostname\n- class\n- nginx::files\n- node\n- hostname\n\’, NULL, 0, \‘unchanged\’)‘) – 0 failed attempts

It is 1.2.18. On 1.2.12 all good.

#7 Updated by Sebastian Lehn over 3 years ago

I entered the same error today. With a simple DB-change it passed away.

ALTER TABLE delayed_job_failures MODIFY details BLOB;

My error message said: …. Report.create_from_yaml_file failed with ActiveRecord::StatementInvalid: Mysql::Error: Incorrect string value: ‘\xE4he f\xFC…’ for column ‘details’ at row 1: INSERT INTO delayed_job_failures … which means there is invalid utf8-code within the value for column details. I suggest BLOB is here the better choice, especially because we never know which kind of error message will appear.

My Dashboard Version: 1.2.20

#8 Updated by Aaron Stone about 3 years ago

Sebastian Lehn wrote:

I entered the same error today. With a simple DB-change it passed away.

ALTER TABLE delayed_job_failures MODIFY details BLOB;

This makes a lot more sense than TEXT. I’ll see about adding a migration for Dashboard 1.3 / Rails 3.

#9 Updated by Aaron Stone about 3 years ago

  • Status changed from Unreviewed to Accepted
  • Assignee set to Aaron Stone

#10 Updated by Alexander Fisher about 3 years ago

Reports can sometimes be quite big. If migrating to BLOB, consider using LONGBLOB instead. See my bug report here. https://projects.puppetlabs.com/issues/20482

Also, as well as modifying delayed_job_failures.details, shouldn’t you also be modifying report_logs.message as well (such that the job doesn’t fail in the first place)?

Kind Regards, Alex

Also available in: Atom PDF