Defect #14391

"stack level too deep" error in lib/active_support/callbacks.rb:409 when setting a dev time

Added by Olivier Houdas over 4 years ago. Updated over 3 years ago.

Status:ClosedStart date:
Priority:NormalDue date:
Assignee:-% Done:

0%

Category:Issues
Target version:-
Resolution:Cant reproduce Affected version:2.3.1

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.

production.zip - log at DEBUG level inlcuding Ruby callstack output in callbacks.rb:409 (21.7 KB) Olivier Houdas, 2013-07-24 12:32

History

#1 Updated by Etienne Massip over 4 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.

#2 Updated by Olivier Houdas over 4 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"}
 (1.7ms) EXEC sp_executesql N'SELECT MAX AS max_id FROM [settings]'
User Load (1.2ms) 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]]
Current user: olivier (id=128)
Issue Load (8.8ms) EXEC sp_executesql N'SELECT TOP (1) [issues].* FROM [issues] WHERE [issues].[id] = @0', N'@0 int', @0 = 15363 [["id", "15363"]]
Project Load (1.2ms) EXEC sp_executesql N'SELECT TOP (1) [projects].* FROM [projects] WHERE [projects].[id] = 19'
EnabledModule Load (1.4ms) EXEC sp_executesql N'SELECT name FROM [enabled_modules] WHERE [enabled_modules].[project_id] = 19'
TimeEntryActivity Load (1.7ms) 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'
Tracker Load (1.5ms) EXEC sp_executesql N'SELECT TOP (1) [trackers].* FROM [trackers] WHERE [trackers].[id] = 1'
IssueCustomField Load (1.8ms) 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'
IssueCustomField Load (1.2ms) EXEC 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'
IssueCustomField Load (1.5ms) 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'
SQL (2.1ms) EXEC 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'
Project Load (2.9ms) 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''))'
IssueStatus Load (1.0ms) EXEC sp_executesql N'SELECT TOP (1) [issue_statuses].* FROM [issue_statuses] WHERE [issue_statuses].[id] = 3'
Role Load (1.5ms) EXEC sp_executesql N'SELECT [roles].* FROM [roles]'
User Load (1.1ms) EXEC sp_executesql N'SELECT TOP (1) [users].* FROM [users] WHERE [users].[type] IN (N''User'', N''AnonymousUser'') AND [users].[id] = 25'
WorkflowTransition Load (1.4ms) 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))'
IssueStatus Load (1.4ms) EXEC sp_executesql N'SELECT [issue_statuses].* FROM [issue_statuses] WHERE [issue_statuses].[id] IN (N''1'', N''2'', N''4'', N''5'', N''6'')'
IssueRelation Load (1.5ms) EXEC sp_executesql N'SELECT [issue_relations].* FROM [issue_relations] WHERE [issue_relations].[issue_to_id] = 15363'
CACHE (0.0ms) SELECT [roles].* FROM [roles]
WorkflowPermission Load (1.5ms) 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)'
CACHE (0.0ms) 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'))
CACHE (0.0ms) SELECT TOP (1) [trackers].* FROM [trackers] WHERE [trackers].[id] = 1
CACHE (0.0ms) SELECT [roles].* FROM [roles]
CACHE (0.0ms) 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)
CACHE (0.0ms) SELECT TOP (1) [issue_statuses].* FROM [issue_statuses] WHERE [issue_statuses].[id] = 3
CACHE (0.0ms) SELECT [roles].* FROM [roles]
CACHE (0.0ms) 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))
CACHE (0.0ms) SELECT [issue_statuses].* FROM [issue_statuses] WHERE [issue_statuses].[id] IN (N'1', N'2', N'4', N'5', N'6')
CACHE (0.0ms) 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'))
CACHE (0.0ms) SELECT TOP (1) [issue_statuses].* FROM [issue_statuses] WHERE [issue_statuses].[id] = 3
CACHE (0.0ms) SELECT [roles].* FROM [roles]
CACHE (0.0ms) 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))
CACHE (0.0ms) SELECT [issue_statuses].* FROM [issue_statuses] WHERE [issue_statuses].[id] IN (N'1', N'2', N'4', N'5', N'6')
CACHE (0.0ms) SELECT [roles].* FROM [roles]
CACHE (0.0ms) 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)
CACHE (0.0ms) SELECT [roles].* FROM [roles]
CACHE (0.0ms) 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)
CACHE (0.0ms) SELECT [roles].* FROM [roles]
CACHE (0.0ms) 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)
CACHE (0.0ms) SELECT [roles].* FROM [roles]
CACHE (0.0ms) 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)
CACHE (0.0ms) SELECT [roles].* FROM [roles]
CACHE (0.0ms) 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)
CACHE (0.0ms) SELECT [roles].* FROM [roles]
CACHE (0.0ms) 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)
CACHE (0.0ms) SELECT [roles].* FROM [roles]
CACHE (0.0ms) 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)
CACHE (0.0ms) 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
CACHE (0.0ms) SELECT TOP (1) [issue_statuses].* FROM [issue_statuses] WHERE [issue_statuses].[id] = 3
CACHE (0.0ms) SELECT [roles].* FROM [roles]
CACHE (0.0ms) 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))
CACHE (0.0ms) SELECT [issue_statuses].* FROM [issue_statuses] WHERE [issue_statuses].[id] IN (N'1', N'2', N'4', N'5', N'6')
SQL (1.2ms) BEGIN TRANSACTION
UserPreference Load (1.7ms) EXEC sp_executesql N'SELECT TOP (1) [user_preferences].* FROM [user_preferences] WHERE [user_preferences].[user_id] = 128'
SQL (1.4ms) IF
@TRANCOUNT > 0 ROLLBACK TRANSACTION
CACHE (0.0ms) SELECT @@TRANCOUNT
Completed 500 Internal Server Error in 3183ms

SystemStackError (stack level too deep):
activesupport (3.2.13) lib/active_support/callbacks.rb:409

#3 Updated by Etienne Massip over 4 years ago

Don't you have any more lines right after this last one? I mea?n, the remaining stack trace

#4 Updated by Olivier Houdas over 4 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.

#5 Updated by Olivier Houdas over 4 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?

#6 Updated by Olivier Houdas over 4 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"

#7 Updated by Miguel Coxo over 4 years ago

We have the same problem on Linux Centos and Oracle DB (I know, I know its not supported ...).

#8 Updated by Etienne Massip over 4 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?

#9 Updated by Olivier Houdas over 4 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"}
 (1.8ms) EXEC sp_executesql N'SELECT MAX AS max_id FROM [settings]'
User Load (1.6ms) 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
Current user: olivier (id=128)
Issue Load (9.2ms) EXEC sp_executesql N'SELECT TOP (1) [issues].* FROM [issues] WHERE [issues].[id] = @0', N'@0 int', @0 = 15363 "id", "15363"
Project Load (1.4ms) EXEC sp_executesql N'SELECT TOP (1) [projects].* FROM [projects] WHERE [projects].[id] = 19'
EnabledModule Load (1.1ms) EXEC sp_executesql N'SELECT name FROM [enabled_modules] WHERE [enabled_modules].[project_id] = 19'
UserPreference Load (1.3ms) EXEC sp_executesql N'SELECT TOP (1) [user_preferences].* FROM [user_preferences] WHERE [user_preferences].[user_id] = 128'
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.

#10 Updated by Etienne Massip over 4 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?

#11 Updated by Olivier Houdas over 4 years ago

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...

#12 Updated by Etienne Massip over 4 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?

1 http://projects.andriylesyuk.com/issues/2181

#13 Updated by Olivier Houdas over 4 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
  UserPreference Load (1.0ms)  EXEC sp_executesql N'SELECT TOP (1) [user_preferences].* FROM [user_preferences] WHERE [user_preferences].[user_id] = 128'
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...

#14 Updated by Etienne Massip over 4 years ago

It'd be perfect if you could log k value as well :)

#15 Updated by Olivier Houdas over 4 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.

#16 Updated by Olivier Houdas about 4 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.

#17 Updated by Daniel Felix about 4 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.

#18 Updated by Olivier Houdas about 4 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...

#19 Updated by Daniel Felix about 4 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.

#20 Updated by Olivier Houdas about 4 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.

#21 Updated by Olivier Houdas about 4 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.

#22 Updated by Toshi MARUYAMA almost 4 years ago

  • Status changed from Needs feedback to Closed

Thank you for your feedback.

#23 Updated by Jesper Grann Laursen over 3 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

Also available in: Atom PDF