Defect #14391
closed"stack level too deep" error in lib/active_support/callbacks.rb:409 when setting a dev time
Added by Olivier Houdas over 11 years ago. Updated over 10 years ago.
0%
Description
Steps :
1. On an existing bug, Choose to update
2. Enter an activity time (1h) and an activity type (Dev), Submit
Result : Internal error, and in the log, we have: Started PUT "/redmine/issues/15363" for 193.xxx.xxx.xxx at 2013-07-03 13:02:58 +0200 Processing by IssuesController#update as HTML Parameters: {"utf8"=>"✓", "authenticity_token"=>"wsTB11rdgHduC2Q/6TCBUN0CZp+34XD6yH42d9A8GcM=", "issue"=>{"is_private"=>"0", "project_id"=>"19", "tracker_id"=>"1", "subject"=>"Certains titres de bugs sont tronqués lors du passage automatique de Mantis à Gertrud", "description"=>"Envoyé par courriel à : name1@xyz.com;name2@xyz.com;\r\n\r\nEtapes pour repro:\r\n1. Saisir un nouveau bug dans http://gss.geoconcept.com/mantis/, avec un long titre (ou peut-être est-ce dû à certains caractères non gérés?)\r\n2. aller voir dans gertrud (par exemple, #15362)\r\nRésultat obtenu : titre coupé\r\nRésultat attendu : titre complet\r\n", "status_id"=>"3", "priority_id"=>"12", "assigned_to_id"=>"128", "category_id"=>"159", "fixed_version_id"=>"966", "parent_issue_id"=>"", "start_date"=>"", "due_date"=>"", "estimated_hours"=>"", "custom_field_values"=>{"2"=>"964", "3"=>"1", "4"=>["Win XP", ""], "5"=>"", "7"=>["Français", ""], "8"=>"0"}, "notes"=>"", "private_notes"=>"0", "lock_version"=>"2"}, "time_entry"=>{"hours"=>"1", "activity_id"=>"19", "comments"=>""}, "last_journal_id"=>"141326", "commit"=>"Soumettre", "id"=>"15363"} Current user: olivier (id=128) Completed 500 Internal Server Error in 774ms SystemStackError (stack level too deep): activesupport (3.2.13) lib/active_support/callbacks.rb:409
My configuration:
Environment:
Redmine version 2.3.1.stable
Ruby version 2.0.0 (x86_64-linux)
Rails version 3.2.13
Environment production
Database adapter SQLServer
Redmine plugins:
extended_fields 0.2.1
redmine_default_columns 0.1.1
redmine_plugin_views_revisions 0.0.1
Note that I have tested removing the 3 plugins I have (Extended fields, Views_revisions and default_columns), and I still reproduced.
I also updated Ruby from 1.9.3 to 2.0.0 as I saw #13327, but this did not fix my issue.
Files
production.zip (21.7 KB) production.zip | log at DEBUG level inlcuding Ruby callstack output in callbacks.rb:409 | Olivier Houdas, 2013-07-24 12:32 |
Updated by Etienne Massip over 11 years ago
- Status changed from New to Needs feedback
- Resolution set to Cant reproduce
Can't reproduce on 1.9.3.
Could you please post the full stack trace?
What OS are you running the Redmine instance on? Ok, got it.
Updated by Olivier Houdas over 11 years ago
I'm not- sure this is the log that you expect, but I activated the ::DEBUG level in config/environments.production.rb, and got this:
Started PUT "/redmine/issues/15363" for 193.57.93.218 at 2013-07-09 12:14:42 +0200
Processing by IssuesController#update as HTML
Parameters: {"utf8"=>"✓", "authenticity_token"=>"wsTB11rdgHduC2Q/6TCBUN0CZp+34XD6yH42d9A8GcM=", "issue"=>{"is_private"=>"0", "project_id"=>"19", "tracker_id"=>"1", "subject"=>"Certains titres de bugs sont tronqués lors du passage automatique de Mantis à Gertrud", "description"=>"Envoyé par courriel à : ;\r\n\r\nEtapes pour repro:\r\n1. Saisir un nouveau bug dans , avec un long titre (ou peut-être est-ce dû à certains caractères non gérés?)\r\n2. aller voir dans gertrud (par exemple, #15362)\r\nRésultat obtenu : titre coupé\r\nRésultat attendu : titre complet\r\n", "status_id"=>"3", "priority_id"=>"12", "assigned_to_id"=>"128", "category_id"=>"159", "fixed_version_id"=>"966", "parent_issue_id"=>"", "start_date"=>"", "due_date"=>"", "estimated_hours"=>"", "custom_field_values"=>{"2"=>"964", "3"=>"1", "4"=>["Win XP", ""], "5"=>"", "7"=>["Français", ""], "8"=>"0"}, "notes"=>"test redmine", "private_notes"=>"0", "lock_version"=>"2"}, "time_entry"=>{"hours"=>"1", "activity_id"=>"19", "comments"=>"test redmine"}, "last_journal_id"=>"141326", "commit"=>"Soumettre", "id"=>"15363"}
[1m[36m (1.7ms)[0m [1mEXEC sp_executesql N'SELECT MAX AS max_id FROM [settings]'[0m
[1m[35mUser Load (1.2ms)[0m EXEC sp_executesql N'SELECT TOP (1) [users].* FROM [users] WHERE [users].[type] IN (N''User'', N''AnonymousUser'') AND [users].[status] = 1 AND [users].[id] = 0', N'@0 int', @0 = 128 [["id", 128]]
@TRANCOUNT > 0 ROLLBACK TRANSACTION[0m
Current user: olivier (id=128)
[1m[36mIssue Load (8.8ms)[0m [1mEXEC sp_executesql N'SELECT TOP (1) [issues].* FROM [issues] WHERE [issues].[id] = @0', N'@0 int', @0 = 15363[0m [["id", "15363"]]
[1m[35mProject Load (1.2ms)[0m EXEC sp_executesql N'SELECT TOP (1) [projects].* FROM [projects] WHERE [projects].[id] = 19'
[1m[36mEnabledModule Load (1.4ms)[0m [1mEXEC sp_executesql N'SELECT name FROM [enabled_modules] WHERE [enabled_modules].[project_id] = 19'[0m
[1m[35mTimeEntryActivity Load (1.7ms)[0m EXEC sp_executesql N'SELECT TOP (1) [enumerations].* FROM [enumerations] WHERE [enumerations].[type] IN (N''TimeEntryActivity'') AND [enumerations].[is_default] = 1 ORDER BY enumerations.position ASC'
[1m[36mTracker Load (1.5ms)[0m [1mEXEC sp_executesql N'SELECT TOP (1) [trackers].* FROM [trackers] WHERE [trackers].[id] = 1'[0m
[1m[35mIssueCustomField Load (1.8ms)[0m EXEC sp_executesql N'SELECT [custom_fields].* FROM [custom_fields] WHERE [custom_fields].[type] IN (N''IssueCustomField'') AND [custom_fields].[is_for_all] = 1 ORDER BY position ASC'
[1m[36mIssueCustomField Load (1.2ms)[0m [1mEXEC sp_executesql N'SELECT [custom_fields].* FROM [custom_fields] INNER JOIN [custom_fields_projects] ON [custom_fields].[id] = [custom_fields_projects].[custom_field_id] WHERE [custom_fields].[type] IN (N''IssueCustomField'') AND [custom_fields_projects].[project_id] = 19 ORDER BY custom_fields.position ASC'[0m
[1m[35mIssueCustomField Load (1.5ms)[0m EXEC sp_executesql N'SELECT [custom_fields].* FROM [custom_fields] INNER JOIN [custom_fields_trackers] ON [custom_fields].[id] = [custom_fields_trackers].[custom_field_id] WHERE [custom_fields].[type] IN (N''IssueCustomField'') AND [custom_fields_trackers].[tracker_id] = 1'
[1m[36mSQL (2.1ms)[0m [1mEXEC sp_executesql N'SELECT [custom_values].[id] AS t0_r0, [custom_values].[customized_type] AS t0_r1, [custom_values].[customized_id] AS t0_r2, [custom_values].[custom_field_id] AS t0_r3, [custom_values].[value] AS t0_r4, [custom_fields].[id] AS t1_r0, [custom_fields].[type] AS t1_r1, [custom_fields].[name] AS t1_r2, [custom_fields].[field_format] AS t1_r3, [custom_fields].[possible_values] AS t1_r4, [custom_fields].[regexp] AS t1_r5, [custom_fields].[min_length] AS t1_r6, [custom_fields].[max_length] AS t1_r7, [custom_fields].[is_required] AS t1_r8, [custom_fields].[is_for_all] AS t1_r9, [custom_fields].[is_filter] AS t1_r10, [custom_fields].[position] AS t1_r11, [custom_fields].[searchable] AS t1_r12, [custom_fields].[default_value] AS t1_r13, [custom_fields].[editable] AS t1_r14, [custom_fields].[visible] AS t1_r15, [custom_fields].[multiple] AS t1_r16, [custom_fields].[is_for_new] AS t1_r17, [custom_fields].[hint] AS t1_r18 FROM [custom_values] LEFT OUTER JOIN [custom_fields] ON [custom_fields].[id] = [custom_values].[custom_field_id] WHERE [custom_values].[customized_id] = 15363 AND [custom_values].[customized_type] = N''Issue'' ORDER BY custom_fields.position ASC'[0m
[1m[35mProject Load (2.9ms)[0m EXEC sp_executesql N'SELECT [projects].* FROM [projects] WHERE (projects.status = 1 AND projects.id IN (SELECT em.project_id FROM enabled_modules em WHERE em.name=''issue_tracking''))'
[1m[36mIssueStatus Load (1.0ms)[0m [1mEXEC sp_executesql N'SELECT TOP (1) [issue_statuses].* FROM [issue_statuses] WHERE [issue_statuses].[id] = 3'[0m
[1m[35mRole Load (1.5ms)[0m EXEC sp_executesql N'SELECT [roles].* FROM [roles]'
[1m[36mUser Load (1.1ms)[0m [1mEXEC sp_executesql N'SELECT TOP (1) [users].* FROM [users] WHERE [users].[type] IN (N''User'', N''AnonymousUser'') AND [users].[id] = 25'[0m
[1m[35mWorkflowTransition Load (1.4ms)[0m EXEC sp_executesql N'SELECT [workflows].* FROM [workflows] WHERE [workflows].[type] IN (N''WorkflowTransition'') AND [workflows].[old_status_id] = 3 AND (role_id IN (1,2,3,4,5) AND tracker_id = 1 AND ((author = 0 AND assignee = 0) OR assignee = 1))'
[1m[36mIssueStatus Load (1.4ms)[0m [1mEXEC sp_executesql N'SELECT [issue_statuses].* FROM [issue_statuses] WHERE [issue_statuses].[id] IN (N''1'', N''2'', N''4'', N''5'', N''6'')'[0m
[1m[35mIssueRelation Load (1.5ms)[0m EXEC sp_executesql N'SELECT [issue_relations].* FROM [issue_relations] WHERE [issue_relations].[issue_to_id] = 15363'
[1m[36mCACHE (0.0ms)[0m [1mSELECT [roles].* FROM [roles][0m
[1m[35mWorkflowPermission Load (1.5ms)[0m EXEC sp_executesql N'SELECT [workflows].* FROM [workflows] WHERE [workflows].[type] IN (N''WorkflowPermission'') AND [workflows].[tracker_id] = 1 AND [workflows].[old_status_id] = 3 AND [workflows].[role_id] IN (1, 2, 3, 4, 5)'
[1m[36mCACHE (0.0ms)[0m [1mSELECT [projects].* FROM [projects] WHERE (projects.status = 1 AND projects.id IN (SELECT em.project_id FROM enabled_modules em WHERE em.name='issue_tracking'))[0m
[1m[35mCACHE (0.0ms)[0m SELECT TOP (1) [trackers].* FROM [trackers] WHERE [trackers].[id] = 1
[1m[36mCACHE (0.0ms)[0m [1mSELECT [roles].* FROM [roles][0m
[1m[35mCACHE (0.0ms)[0m SELECT [workflows].* FROM [workflows] WHERE [workflows].[type] IN (N'WorkflowPermission') AND [workflows].[tracker_id] = 1 AND [workflows].[old_status_id] = 3 AND [workflows].[role_id] IN (1, 2, 3, 4, 5)
[1m[36mCACHE (0.0ms)[0m [1mSELECT TOP (1) [issue_statuses].* FROM [issue_statuses] WHERE [issue_statuses].[id] = 3[0m
[1m[35mCACHE (0.0ms)[0m SELECT [roles].* FROM [roles]
[1m[36mCACHE (0.0ms)[0m [1mSELECT [workflows].* FROM [workflows] WHERE [workflows].[type] IN (N'WorkflowTransition') AND [workflows].[old_status_id] = 3 AND (role_id IN (1,2,3,4,5) AND tracker_id = 1 AND ((author = 0 AND assignee = 0) OR assignee = 1))[0m
[1m[35mCACHE (0.0ms)[0m SELECT [issue_statuses].* FROM [issue_statuses] WHERE [issue_statuses].[id] IN (N'1', N'2', N'4', N'5', N'6')
[1m[36mCACHE (0.0ms)[0m [1mSELECT [projects].* FROM [projects] WHERE (projects.status = 1 AND projects.id IN (SELECT em.project_id FROM enabled_modules em WHERE em.name='issue_tracking'))[0m
[1m[35mCACHE (0.0ms)[0m SELECT TOP (1) [issue_statuses].* FROM [issue_statuses] WHERE [issue_statuses].[id] = 3
[1m[36mCACHE (0.0ms)[0m [1mSELECT [roles].* FROM [roles][0m
[1m[35mCACHE (0.0ms)[0m SELECT [workflows].* FROM [workflows] WHERE [workflows].[type] IN (N'WorkflowTransition') AND [workflows].[old_status_id] = 3 AND (role_id IN (1,2,3,4,5) AND tracker_id = 1 AND ((author = 0 AND assignee = 0) OR assignee = 1))
[1m[36mCACHE (0.0ms)[0m [1mSELECT [issue_statuses].* FROM [issue_statuses] WHERE [issue_statuses].[id] IN (N'1', N'2', N'4', N'5', N'6')[0m
[1m[35mCACHE (0.0ms)[0m SELECT [roles].* FROM [roles]
[1m[36mCACHE (0.0ms)[0m [1mSELECT [workflows].* FROM [workflows] WHERE [workflows].[type] IN (N'WorkflowPermission') AND [workflows].[tracker_id] = 1 AND [workflows].[old_status_id] = 3 AND [workflows].[role_id] IN (1, 2, 3, 4, 5)[0m
[1m[35mCACHE (0.0ms)[0m SELECT [roles].* FROM [roles]
[1m[36mCACHE (0.0ms)[0m [1mSELECT [workflows].* FROM [workflows] WHERE [workflows].[type] IN (N'WorkflowPermission') AND [workflows].[tracker_id] = 1 AND [workflows].[old_status_id] = 3 AND [workflows].[role_id] IN (1, 2, 3, 4, 5)[0m
[1m[35mCACHE (0.0ms)[0m SELECT [roles].* FROM [roles]
[1m[36mCACHE (0.0ms)[0m [1mSELECT [workflows].* FROM [workflows] WHERE [workflows].[type] IN (N'WorkflowPermission') AND [workflows].[tracker_id] = 1 AND [workflows].[old_status_id] = 3 AND [workflows].[role_id] IN (1, 2, 3, 4, 5)[0m
[1m[35mCACHE (0.0ms)[0m SELECT [roles].* FROM [roles]
[1m[36mCACHE (0.0ms)[0m [1mSELECT [workflows].* FROM [workflows] WHERE [workflows].[type] IN (N'WorkflowPermission') AND [workflows].[tracker_id] = 1 AND [workflows].[old_status_id] = 3 AND [workflows].[role_id] IN (1, 2, 3, 4, 5)[0m
[1m[35mCACHE (0.0ms)[0m SELECT [roles].* FROM [roles]
[1m[36mCACHE (0.0ms)[0m [1mSELECT [workflows].* FROM [workflows] WHERE [workflows].[type] IN (N'WorkflowPermission') AND [workflows].[tracker_id] = 1 AND [workflows].[old_status_id] = 3 AND [workflows].[role_id] IN (1, 2, 3, 4, 5)[0m
[1m[35mCACHE (0.0ms)[0m SELECT [roles].* FROM [roles]
[1m[36mCACHE (0.0ms)[0m [1mSELECT [workflows].* FROM [workflows] WHERE [workflows].[type] IN (N'WorkflowPermission') AND [workflows].[tracker_id] = 1 AND [workflows].[old_status_id] = 3 AND [workflows].[role_id] IN (1, 2, 3, 4, 5)[0m
[1m[35mCACHE (0.0ms)[0m SELECT [roles].* FROM [roles]
[1m[36mCACHE (0.0ms)[0m [1mSELECT [workflows].* FROM [workflows] WHERE [workflows].[type] IN (N'WorkflowPermission') AND [workflows].[tracker_id] = 1 AND [workflows].[old_status_id] = 3 AND [workflows].[role_id] IN (1, 2, 3, 4, 5)[0m
[1m[35mCACHE (0.0ms)[0m SELECT [custom_fields].* FROM [custom_fields] INNER JOIN [custom_fields_trackers] ON [custom_fields].[id] = [custom_fields_trackers].[custom_field_id] WHERE [custom_fields].[type] IN (N'IssueCustomField') AND [custom_fields_trackers].[tracker_id] = 1
[1m[36mCACHE (0.0ms)[0m [1mSELECT TOP (1) [issue_statuses].* FROM [issue_statuses] WHERE [issue_statuses].[id] = 3[0m
[1m[35mCACHE (0.0ms)[0m SELECT [roles].* FROM [roles]
[1m[36mCACHE (0.0ms)[0m [1mSELECT [workflows].* FROM [workflows] WHERE [workflows].[type] IN (N'WorkflowTransition') AND [workflows].[old_status_id] = 3 AND (role_id IN (1,2,3,4,5) AND tracker_id = 1 AND ((author = 0 AND assignee = 0) OR assignee = 1))[0m
[1m[35mCACHE (0.0ms)[0m SELECT [issue_statuses].* FROM [issue_statuses] WHERE [issue_statuses].[id] IN (N'1', N'2', N'4', N'5', N'6')
[1m[36mSQL (1.2ms)[0m [1mBEGIN TRANSACTION[0m
[1m[35mUserPreference Load (1.7ms)[0m EXEC sp_executesql N'SELECT TOP (1) [user_preferences].* FROM [user_preferences] WHERE [user_preferences].[user_id] = 128'
[1m[36mSQL (1.4ms)[0m [1mIF
[1m[35mCACHE (0.0ms)[0m SELECT @@TRANCOUNT
Completed 500 Internal Server Error in 3183ms
SystemStackError (stack level too deep):
activesupport (3.2.13) lib/active_support/callbacks.rb:409
Updated by Etienne Massip over 11 years ago
Don't you have any more lines right after this last one? I mea?n, the remaining stack trace
Updated by Olivier Houdas over 11 years ago
No, this is the end of the log, and if I try again, the new action's log is saved right after this, I'm afraid.
If there is a mean to activate some more logs, please tell me, I have full access to the server, I'm testing our migration from MySQL to SQL server on a test machine.
Updated by Olivier Houdas over 11 years ago
Actually, even simply clicking the Log time link on any issue will raise the same error.
Did you try to reproduce using an MS SQL server?
Updated by Olivier Houdas over 11 years ago
Hi, here are new steps to reproduce, as you look not convinced:
1. Install Redmine 2.3.1.stable on Linux Centos
2. Create a database in Microsoft SQL, populate it with the migration command, start Redmine
3. Open the site, then click on Projects
4. Click on New project, give a name, keep all defaults
5. Create a new Issue, just type test/test for title/body, create the issue
6. Click on Log time on the issue displayed
Result : Internal error. In the log, we can read:
"SystemStackError (stack level too deep):
activesupport (3.2.13) lib/active_support/callbacks.rb:409"
Updated by Miguel Coxo over 11 years ago
We have the same problem on Linux Centos and Oracle DB (I know, I know its not supported ...).
Updated by Etienne Massip over 11 years ago
Olivier Houdas wrote:
Hi, here are new steps to reproduce, as you look not convinced:
I'm convinced you got the error, but I think it might be a CentOS related issue.
Could you please remove the Rails.backtrace_cleaner.remove_silencers! line from your config/initializers/backtrace_silencers.rb
file, restart your instance, trigger again the error and get the full exception stack trace?
Updated by Olivier Houdas over 11 years ago
Thank you for your feedback.
I activated DEBUG log level, uncommented the remove_silencers! line, but still it stops on the same text in the log:
Processing by TimelogController#new as HTML
Parameters: {"issue_id"=>"15363"}
[1m[35m (1.8ms)[0m EXEC sp_executesql N'SELECT MAX AS max_id FROM [settings]'
[1m[36mUser Load (1.6ms)[0m [1mEXEC sp_executesql N'SELECT TOP (1) [users].* FROM [users] WHERE [users].[type] IN (N''User'', N''AnonymousUser'') AND [users].[status] = 1 AND [users].[id] = @0', N'@0 int', @0 = 128[0m "id", 128
Current user: olivier (id=128)
[1m[35mIssue Load (9.2ms)[0m EXEC sp_executesql N'SELECT TOP (1) [issues].* FROM [issues] WHERE [issues].[id] = Rangicaadmice Rangicaadmice', N'@0 int', Rangicaadmice Rangicaadmice = 15363 "id", "15363"
[1m[36mProject Load (1.4ms)[0m [1mEXEC sp_executesql N'SELECT TOP (1) [projects].* FROM [projects] WHERE [projects].[id] = 19'[0m
[1m[35mEnabledModule Load (1.1ms)[0m EXEC sp_executesql N'SELECT name FROM [enabled_modules] WHERE [enabled_modules].[project_id] = 19'
[1m[36mUserPreference Load (1.3ms)[0m [1mEXEC sp_executesql N'SELECT TOP (1) [user_preferences].* FROM [user_preferences] WHERE [user_preferences].[user_id] = 128'[0m
Completed 500 Internal Server Error in 740ms
SystemStackError (stack level too deep):
activesupport (3.2.13) lib/active_support/callbacks.rb:409
Note that your instruction was to remove that line from the file, so I did it, but as it was commented (starting with a #), I also tried to leave it and uncomment it (which makes more sense to me, that is, we are making sure no silencer is active). Anyway, in both cases I got the same last line in the log.
Note also that this log is on the action of clicking Log time link whereas my first log extract was when updating the issue (with time info).
As our machine is used only for Redmine (and it is a backup-able virtual machine), if you need us to try some changes on the CentOS system, we can do it.
Updated by Etienne Massip over 11 years ago
Olivier Houdas wrote:
Note that your instruction was to remove that line from the file, so I did it, but as it was commented (starting with a #), I also tried to leave it and uncomment it (which makes more sense to me, that is, we are making sure no silencer is active). Anyway, in both cases I got the same last line in the log.
Yes, that was a erroneous instruction from me, you should have uncomment it indeed.
I'm a bit surprised it doesn't change anything though, did you restart the web server or whatever is hosting the app?
Updated by Olivier Houdas over 11 years ago
- File production.zip production.zip added
Hi,
Yes, we restarted with service httpd restart...
OK. We tried something more advanced: we modified Ruby active_support\callbacks.rb at line 409 with the following:
def __reset_runner(symbol) Rails.logger.debug("GEOCONCEPT - HELLO WORLD"); Rails.logger.debug(caller(1,10)); name = __callback_runner_name(nil, symbol) undef_method(name) if method_defined?(name) end
We got the string in the log, but when the Internal comes, we don't get more info !
I removed the log I had attached as it was truncated (size limit too small in the log config in production.rb), and is finally not useful.
I will try harder to get some info...
Updated by Etienne Massip over 11 years ago
Note that extended_fields plugin is compatible with Redmine 2.3 starting from version 0.2.21, so you might want to update it?
Updated by Olivier Houdas over 11 years ago
Thank you for the note on Extended_Fields. I did apply some hot fixes to get it to work, indeed. If there is an official release with those fixes, I'll switch to it. Anyway, removing all plugins does not fix the issue, as mentioned in my first comment.
I added some messages the old way, and got a bit further to rebuild the call stack myself:
in app/models/time_entry.rb
def initialize(attributes=nil, * args) Rails.logger.debug("GEOCONCEPT-Ol10"); super Rails.logger.debug("GEOCONCEPT-Ol11");
I get "GEOCONCEPT-Ol10" in the log, but not 11.
In /active_record/base.rb, in the initialize method, it fails in
assign_attributes(attributes, options) if attributes
In /active_record/attribute_assignment.rb it fails in
attributes.each do |k, v| if k.include?("(") multi_parameter_attributes << [ k, v ] elsif respond_to?("#{k}=") if v.is_a?(Hash) nested_parameter_attributes << [ k, v ] else Rails.logger.debug("GEOCONCEPT-O22"); send("#{k}=", v) Rails.logger.debug("GEOCONCEPT-O22b"); end else raise(UnknownAttributeError, "unknown attribute: #{k}") end end
with the following log:
GEOCONCEPT-Ol1 [1m[36mUserPreference Load (1.0ms)[0m [1mEXEC sp_executesql N'SELECT TOP (1) [user_preferences].* FROM [user_preferences] WHERE [user_preferences].[user_id] = 128'[0m GEOCONCEPT-Ol10 GEOCONCEPT-Ol5 GEOCONCEPT-O22 GEOCONCEPT-O22b GEOCONCEPT-O22 GEOCONCEPT-O22b GEOCONCEPT-O22 GEOCONCEPT-O22b GEOCONCEPT-O22 Completed 500 Internal Server Error in 603ms SystemStackError (stack level too deep):
I hope it can be of some help to you...
Updated by Etienne Massip over 11 years ago
It'd be perfect if you could log k value as well :)
Updated by Olivier Houdas over 11 years ago
GEOCONCEPT-O22, k:project
GEOCONCEPT-O22b
GEOCONCEPT-O22, k:issue
GEOCONCEPT-O22b
GEOCONCEPT-O22, k:user
GEOCONCEPT-O22b
GEOCONCEPT-O22, k:spent_on
Completed 500 Internal Server Error in 2257ms
I'm sorry, I had tried to log both k and v, and had got an error, so I hadn't looked further...
It might be an issue with date formats then, I know it's a real pain with DB compatibility.
Updated by Olivier Houdas about 11 years ago
Any news on this bug? This is blocking our migration to Redmine...
Even a hint on where to hotfix the issue ourselves while waiting for an official release would be welcome.
Updated by Daniel Felix about 11 years ago
This error normally won't appear in Redmine. I just encounter this error if I use patches in my plugins.
Please remove all plugins and restart webserver and try it again to see if this error is produced by a plugin.
Sometimes you can escape this error for some time by changing config.cache_classes in your environment, but this won't be a solution for a longer time.
Please give some feedback if your plugins are removed.
Updated by Olivier Houdas about 11 years ago
Thank you for your response.
As indicated in my very first description, I had tried removing plugins as one of the first things.
I did it again, just to be sure:
- renamed the plugins folder to plugins.bak
- change the DB to an empty one (edited config/database.yml, ran bundle install, ran db migration and restarted httpd)
- tested on a new project, new bug created
- clicked on Input time for that bug
Got the internal error again.
As investigated above, I suspect an incompatibility with Microsoft SQL server regarding a date field format ("spent_on" in table time_entries) in a request, but my knowledge and understanding of rails and redmine code does not let me go further...
Updated by Daniel Felix about 11 years ago
Well no, I don't think that this is sql server related. We are using MS SQL Server for our system too. We used it with 2008 R2 and 2012. Both worked pretty well.
Updated by Olivier Houdas about 11 years ago
An update on this bug:
I called a programing guru (my manager) to help unblock me on the subject, and he found a way:
in the Redmine file app/models/time_entry.rb
in the function
def spent_on=(date) super if spent_on.is_a?(Time) self.spent_on = spent_on.to_date end self.tyear = spent_on ? spent_on.year : nil self.tmonth = spent_on ? spent_on.month : nil self.tweek = spent_on ? Date.civil(spent_on.year, spent_on.month, spent_on.day).cweek : nil end
There is a possible infinite loop due to the action on self. We changed it to
def spent_on=(date) if spent_on.is_a?(Time) date = date.to_date end super self.tyear = spent_on ? spent_on.year : nil self.tmonth = spent_on ? spent_on.month : nil self.tweek = spent_on ? Date.civil(spent_on.year, spent_on.month, spent_on.day).cweek : nil end
and now it does not crash anymore.
I don't know if the infinite loop resulting in the stack level too deep was specific to CentOS, specific to MS SQL, specific to a mix of languages (French on the SQL server, English on the Redmine server), or due to something else, but it definitely could be fixed in the Redmine code.
I hope it will help (the Redmine team or some other users)!
Just for info, the value of v.inspect (and therefore of date) was "Thu, 29 Aug 2013" when the endless loop occured.
Updated by Olivier Houdas about 11 years ago
As a conclusion to this issue (please close it - I don't have rights for that action):
Although there is definitely a possibility of endless loop in the current code, the issue appeared only when we used incorrect Date/time field type instead of Date.
This was due to our using SQL server 2005 instead of 2008 which is the earliest version supported by Redmine.
Issue closed.
Updated by Toshi MARUYAMA almost 11 years ago
- Status changed from Needs feedback to Closed
Thank you for your feedback.
Updated by Jesper Grann Laursen over 10 years ago
Just as a note, we are running redmine on a MS SQL 2005, and this is the only error we have found. Oliviers change did also help us. Thanks a lot.
Environment: Redmine version 2.4.3.stable Ruby version 1.9.3-p545 (2014-02-24) [i386-mingw32] Rails version 3.2.16 Environment production Database adapter SQLServer