Project

General

Profile

Actions

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 10 years ago. Updated almost 10 years ago.

Status:
Closed
Priority:
Normal
Assignee:
-
Category:
Issues
Target version:
-
Start date:
Due date:
% Done:

0%

Estimated time:
Resolution:
Cant reproduce
Affected version:

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
Actions #1

Updated by Etienne Massip over 10 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.

Actions #2

Updated by Olivier Houdas over 10 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]]
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
@TRANCOUNT > 0 ROLLBACK TRANSACTION[0m
[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

Actions #3

Updated by Etienne Massip over 10 years ago

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

Actions #4

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

Actions #5

Updated by Olivier Houdas over 10 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?

Actions #6

Updated by Olivier Houdas over 10 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"

Actions #7

Updated by Miguel Coxo over 10 years ago

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

Actions #8

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

Actions #9

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

Actions #10

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

Actions #11

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

Actions #12

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

Actions #13

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

Actions #14

Updated by Etienne Massip over 10 years ago

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

Actions #15

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

Actions #16

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

Actions #17

Updated by Daniel Felix over 10 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.

Actions #18

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

Actions #19

Updated by Daniel Felix over 10 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.

Actions #20

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

Actions #21

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

Actions #22

Updated by Toshi MARUYAMA over 10 years ago

  • Status changed from Needs feedback to Closed

Thank you for your feedback.

Actions #23

Updated by Jesper Grann Laursen almost 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

Actions

Also available in: Atom PDF