Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

JSON lexer spins in infinite loop #1330

Closed
stanhu opened this issue Sep 16, 2019 · 10 comments · Fixed by #1331
Closed

JSON lexer spins in infinite loop #1330

stanhu opened this issue Sep 16, 2019 · 10 comments · Fixed by #1331
Assignees
Labels
bugfix-request A request for a bugfix to be developed.

Comments

@stanhu
Copy link
Contributor

stanhu commented Sep 16, 2019

Name of the lexer

JSON in Rouge v3.10.0

Code sample

diff --git a/spec/visual/samples/json b/spec/visual/samples/json
index 8ab07017..d033530c 100644
--- a/spec/visual/samples/json
+++ b/spec/visual/samples/json
@@ -140,3 +140,7 @@ null
                (SELECT max(\"ci_builds\".id) FROM \"ci_builds\" WHERE
                \"ci_builds\".\"commit_id\" = $2 GROUP BY
                \"ci_builds\".\"name\", \"ci_builds\".\"commit_id\")" }
+
+    {"severity":"WARN","time":"2019-07-18T14:39:51.091Z","class":"BackgroundMigrationWorker","retry":3,"queue":"background_migration","jid":"7e716ce7e40b6c6a1fc1a647","created_at":"2019-07-18T14:15:32.453Z","correlation_id":"5c06ecbd-21da-4906-a35d-f3e51f4e0048","enqueued_at":"2019-07-18T14:39:51.000Z","error_message":"Sidekiq::JobRetry::Skip","error_class":"NameError","failed_at":"2019-07-18T14:17:02.563Z","retry_count":0,"pid":30739,"message":"BackgroundMigrationWorker JID-7e716ce7e40b6c6a1fc1a647: fail: 0.09 sec","job_status":"fail","duration":0.09,"completed_at":"2019-07-18T14:39:51.091Z","error":{},"error_backtrace":["/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/job_retry.rb:127:in `rescue in local'","/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/job_retry.rb:108:in `local'","/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:136:in `block (5 levels) in dispatch'","/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/rails.rb:43:in `block in call'","/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/activesupport-5.1.7/lib/active_support/execution_wrapper.rb:85:in `wrap'","/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/activesupport-5.1.7/lib/active_support/reloader.rb:68:in `block in wrap'","/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/activesupport-5.1.7/lib/active_support/execution_wrapper.rb:85:in `wrap'","/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/activesupport-5.1.7/lib/active_support/reloader.rb:67:in `wrap'","/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/rails.rb:42:in `call'","/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:132:in `block (4 levels) in dispatch'","/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:250:in `stats'","/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:127:in `block (3 levels) in dispatch'","/opt/gitlab/embedded/service/gitlab-rails/lib/gitlab/sidekiq_logging/structured_logger.rb:16:in `call'","/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:126:in `block (2 levels) in dispatch'","/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/job_retry.rb:74:in `global'","/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:125:in `block in dispatch'","/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/logging.rb:48:in `with_context'","/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/logging.rb:42:in `with_job_hash_context'","/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:124:in `dispatch'","/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:163:in `process'","/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:83:in `process_one'","/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:71:in `run'","/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/util.rb:16:in `watchdog'","/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/util.rb:25:in `block in safe_thread'"]}{"severity":"WARN","time":"2019-07-18T14:39:51.092Z","message":"{\"context\":\"Job raised exception\",\"job\":{\"class\":\"BackgroundMigrationWorker\",\"args\":[\"Gitlab::BackgroundMigration::PruneOrphanedGeoEvents\",\"geo_repositories_changed_events\"],\"retry\":3,\"queue\":\"background_migration\",\"jid\":\"7e716ce7e40b6c6a1fc1a647\",\"created_at\":1563459332.4537215,\"correlation_id\":\"5c06ecbd-21da-4906-a35d-f3e51f4e0048\",\"enqueued_at\":1563460791.0008795,\"error_message\":\"uninitialized constant Gitlab::BackgroundMigration::PruneOrphanedGeoEvents\\nDid you mean?  PruneOldEventsWorker\",\"error_class\":\"NameError\",\"failed_at\":1563459422.5637114,\"retry_count\":0},\"jobstr\":\"{\\\"class\\\":\\\"BackgroundMigrationWorker\\\",\\\"args\\\":[\\\"Gitlab::BackgroundMigration::PruneOrphanedGeoEvents\\\",\\\"geo_repositories_changed_events\\\"],\\\"retry\\\":3,\\\"queue\\\":\\\"background_migration\\\",\\\"jid\\\":\\\"7e716ce7e40b6c6a1fc1a647\\\",\\\"created_at\\\":1563459332.4537215,\\\"correlation_id\\\":\\\"5c06ecbd-21da-4906-a35d-f3e51f4e0048\\\",\\\"enqueued_at\\\":1563460791.0008795,\\\"error_message\\\":\\\"uninitialized constant Gitlab::BackgroundMigration::PruneOrphanedGeoEvents\\\\nDid you mean?  PruneOldEventsWorker\\\",\\\"error_class\\\":\\\"NameError\\\",\\\"failed_at\\\":1563459422.5637114,\\\"retry_count\\\":0}\"}"}
+    {"severity":"WARN","time":"2019-07-18T14:39:51.092Z","message":"NameError: uninitialized constant Gitlab::BackgroundMigration::PruneOrphanedGeoEvents\nDid you mean?  PruneOldEventsWorker"}
+    {"severity":"WARN","time":"2019-07-18T14:39:51.092Z","message":"/opt/gitlab/embedded/service/gitlab-rails/lib/gitlab/background_migration.rb:81:in `const_get'\n/opt/gitlab/embedded/service/gitlab-rails/lib/gitlab/background_migration.rb:81:in `migration_class_for'\n/opt/gitlab/embedded/service/gitlab-rails/lib/gitlab/background_migration.rb:58:in `perform'\n/opt/gitlab/embedded/service/gitlab-rails/app/workers/background_migration_worker.rb:26:in `perform'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:192:in `execute_job'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:165:in `block (2 levels) in process'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/middleware/chain.rb:128:in `block in invoke'\n/opt/gitlab/embedded/service/gitlab-rails/lib/gitlab/sidekiq_status/server_middleware.rb:7:in `call'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/middleware/chain.rb:130:in `block in invoke'\n/opt/gitlab/embedded/service/gitlab-rails/lib/gitlab/sidekiq_middleware/correlation_logger.rb:10:in `block in call'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/gitlab-labkit-0.3.0/lib/labkit/correlation/correlation_id.rb:18:in `use_id'\n/opt/gitlab/embedded/service/gitlab-rails/lib/gitlab/sidekiq_middleware/correlation_logger.rb:9:in `call'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/middleware/chain.rb:130:in `block in invoke'\n/opt/gitlab/embedded/service/gitlab-rails/lib/gitlab/sidekiq_middleware/batch_loader.rb:7:in `call'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/middleware/chain.rb:130:in `block in invoke'\n/opt/gitlab/embedded/service/gitlab-rails/lib/gitlab/sidekiq_middleware/request_store_middleware.rb:8:in `call'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/middleware/chain.rb:130:in `block in invoke'\n/opt/gitlab/embedded/service/gitlab-rails/lib/gitlab/sidekiq_middleware/memory_killer.rb:18:in `call'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/middleware/chain.rb:130:in `block in invoke'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sentry-raven-2.9.0/lib/raven/integrations/sidekiq.rb:9:in `call'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/middleware/chain.rb:130:in `block in invoke'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/middleware/chain.rb:133:in `invoke'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:164:in `block in process'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:137:in `block (6 levels) in dispatch'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/job_retry.rb:109:in `local'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:136:in `block (5 levels) in dispatch'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/rails.rb:43:in `block in call'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/activesupport-5.1.7/lib/active_support/execution_wrapper.rb:85:in `wrap'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/activesupport-5.1.7/lib/active_support/reloader.rb:68:in `block in wrap'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/activesupport-5.1.7/lib/active_support/execution_wrapper.rb:85:in `wrap'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/activesupport-5.1.7/lib/active_support/reloader.rb:67:in `wrap'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/rails.rb:42:in `call'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:132:in `block (4 levels) in dispatch'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:250:in `stats'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:127:in `block (3 levels) in dispatch'\n/opt/gitlab/embedded/service/gitlab-rails/lib/gitlab/sidekiq_logging/structured_logger.rb:16:in `call'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:126:in `block (2 levels) in dispatch'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/job_retry.rb:74:in `global'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:125:in `block in dispatch'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/logging.rb:48:in `with_context'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/logging.rb:42:in `with_job_hash_context'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:124:in `dispatch'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:163:in `process'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:83:in `process_one'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:71:in `run'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/util.rb:16:in `watchdog'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/util.rb:25:in `block in safe_thread'"}

Screenshots
If applicable, add screenshots to help explain your problem.

Additional context

Calling rb_backtrace() in GDB shows this output:

        from /opt/gitlab/embedded/service/gitlab-rails/lib/rouge/formatters/html_gitlab.rb:18:in `stream'
        from /opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/rouge-3.10.0/lib/rouge/formatter.rb:96:in `token_lines'
        from /opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/rouge-3.10.0/lib/rouge/formatter.rb:96:in `each'
        from /opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/rouge-3.10.0/lib/rouge/formatter.rb:58:in `filter_escapes'
        from /opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/rouge-3.10.0/lib/rouge/formatter.rb:58:in `each'
        from /opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/rouge-3.10.0/lib/rouge/lexer.rb:448:in `lex'
        from /opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/rouge-3.10.0/lib/rouge/lexer.rb:458:in `continue_lex'
        from /opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/rouge-3.10.0/lib/rouge/regex_lexer.rb:272:in `stream_tokens'
        from /opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/rouge-3.10.0/lib/rouge/regex_lexer.rb:291:in `step'
        from /opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/rouge-3.10.0/lib/rouge/regex_lexer.rb:291:in `each'
        from /opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/rouge-3.10.0/lib/rouge/regex_lexer.rb:294:in `block in step'
        from /opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/rouge-3.10.0/lib/rouge/regex_lexer.rb:291:in `step'
        from /opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/rouge-3.10.0/lib/rouge/regex_lexer.rb:291:in `each'
        from /opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/rouge-3.10.0/lib/rouge/regex_lexer.rb:306:in `block in step'
        from /opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/rouge-3.10.0/lib/rouge/regex_lexer.rb:306:in `skip'

This problem appears to have started in Rouge v3.8.0. v3.7.0 works fine.

@stanhu stanhu added the bugfix-request A request for a bugfix to be developed. label Sep 16, 2019
@stanhu
Copy link
Contributor Author

stanhu commented Sep 16, 2019

Reverting https://github.com/rouge-ruby/rouge/pull/1297/files seems to fix this problem.

@stanhu
Copy link
Contributor Author

stanhu commented Sep 16, 2019

@pyrmont Thanks for your work on this gem! It looks like we're going to revert to v3.7.0 until this bug is fixed.

@pyrmont
Copy link
Contributor

pyrmont commented Sep 16, 2019

@stanhu I'm a little unclear as to what precisely the source text is. Is the problem all the text you copied and pasted (notwithstanding that it's the output of diff) or is the problem the text in the diff'd sample?

@stanhu
Copy link
Contributor Author

stanhu commented Sep 16, 2019

@pyrmont It's the latter. The diff is the reproduction case.

@pyrmont
Copy link
Contributor

pyrmont commented Sep 16, 2019

@stanhu Forgive me but could you paste below just the source that's the problem?

@pyrmont pyrmont self-assigned this Sep 16, 2019
@stanhu
Copy link
Contributor Author

stanhu commented Sep 16, 2019

@pyrmont Sure, I think it's this:

    {"severity":"WARN","time":"2019-07-18T14:39:51.091Z","class":"BackgroundMigrationWorker","retry":3,"queue":"background_migration","jid":"7e716ce7e40b6c6a1fc1a647","created_at":"2019-07-18T14:15:32.453Z","correlation_id":"5c06ecbd-21da-4906-a35d-f3e51f4e0048","enqueued_at":"2019-07-18T14:39:51.000Z","error_message":"Sidekiq::JobRetry::Skip","error_class":"NameError","failed_at":"2019-07-18T14:17:02.563Z","retry_count":0,"pid":30739,"message":"BackgroundMigrationWorker JID-7e716ce7e40b6c6a1fc1a647: fail: 0.09 sec","job_status":"fail","duration":0.09,"completed_at":"2019-07-18T14:39:51.091Z","error":{},"error_backtrace":["/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/job_retry.rb:127:in `rescue in local'","/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/job_retry.rb:108:in `local'","/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:136:in `block (5 levels) in dispatch'","/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/rails.rb:43:in `block in call'","/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/activesupport-5.1.7/lib/active_support/execution_wrapper.rb:85:in `wrap'","/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/activesupport-5.1.7/lib/active_support/reloader.rb:68:in `block in wrap'","/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/activesupport-5.1.7/lib/active_support/execution_wrapper.rb:85:in `wrap'","/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/activesupport-5.1.7/lib/active_support/reloader.rb:67:in `wrap'","/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/rails.rb:42:in `call'","/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:132:in `block (4 levels) in dispatch'","/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:250:in `stats'","/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:127:in `block (3 levels) in dispatch'","/opt/gitlab/embedded/service/gitlab-rails/lib/gitlab/sidekiq_logging/structured_logger.rb:16:in `call'","/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:126:in `block (2 levels) in dispatch'","/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/job_retry.rb:74:in `global'","/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:125:in `block in dispatch'","/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/logging.rb:48:in `with_context'","/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/logging.rb:42:in `with_job_hash_context'","/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:124:in `dispatch'","/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:163:in `process'","/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:83:in `process_one'","/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:71:in `run'","/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/util.rb:16:in `watchdog'","/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/util.rb:25:in `block in safe_thread'"]}{"severity":"WARN","time":"2019-07-18T14:39:51.092Z","message":"{\"context\":\"Job raised exception\",\"job\":{\"class\":\"BackgroundMigrationWorker\",\"args\":[\"Gitlab::BackgroundMigration::PruneOrphanedGeoEvents\",\"geo_repositories_changed_events\"],\"retry\":3,\"queue\":\"background_migration\",\"jid\":\"7e716ce7e40b6c6a1fc1a647\",\"created_at\":1563459332.4537215,\"correlation_id\":\"5c06ecbd-21da-4906-a35d-f3e51f4e0048\",\"enqueued_at\":1563460791.0008795,\"error_message\":\"uninitialized constant Gitlab::BackgroundMigration::PruneOrphanedGeoEvents\\nDid you mean?  PruneOldEventsWorker\",\"error_class\":\"NameError\",\"failed_at\":1563459422.5637114,\"retry_count\":0},\"jobstr\":\"{\\\"class\\\":\\\"BackgroundMigrationWorker\\\",\\\"args\\\":[\\\"Gitlab::BackgroundMigration::PruneOrphanedGeoEvents\\\",\\\"geo_repositories_changed_events\\\"],\\\"retry\\\":3,\\\"queue\\\":\\\"background_migration\\\",\\\"jid\\\":\\\"7e716ce7e40b6c6a1fc1a647\\\",\\\"created_at\\\":1563459332.4537215,\\\"correlation_id\\\":\\\"5c06ecbd-21da-4906-a35d-f3e51f4e0048\\\",\\\"enqueued_at\\\":1563460791.0008795,\\\"error_message\\\":\\\"uninitialized constant Gitlab::BackgroundMigration::PruneOrphanedGeoEvents\\\\nDid you mean?  PruneOldEventsWorker\\\",\\\"error_class\\\":\\\"NameError\\\",\\\"failed_at\\\":1563459422.5637114,\\\"retry_count\\\":0}\"}"}
    {"severity":"WARN","time":"2019-07-18T14:39:51.092Z","message":"NameError: uninitialized constant Gitlab::BackgroundMigration::PruneOrphanedGeoEvents\nDid you mean?  PruneOldEventsWorker"}
    {"severity":"WARN","time":"2019-07-18T14:39:51.092Z","message":"/opt/gitlab/embedded/service/gitlab-rails/lib/gitlab/background_migration.rb:81:in `const_get'\n/opt/gitlab/embedded/service/gitlab-rails/lib/gitlab/background_migration.rb:81:in `migration_class_for'\n/opt/gitlab/embedded/service/gitlab-rails/lib/gitlab/background_migration.rb:58:in `perform'\n/opt/gitlab/embedded/service/gitlab-rails/app/workers/background_migration_worker.rb:26:in `perform'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:192:in `execute_job'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:165:in `block (2 levels) in process'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/middleware/chain.rb:128:in `block in invoke'\n/opt/gitlab/embedded/service/gitlab-rails/lib/gitlab/sidekiq_status/server_middleware.rb:7:in `call'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/middleware/chain.rb:130:in `block in invoke'\n/opt/gitlab/embedded/service/gitlab-rails/lib/gitlab/sidekiq_middleware/correlation_logger.rb:10:in `block in call'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/gitlab-labkit-0.3.0/lib/labkit/correlation/correlation_id.rb:18:in `use_id'\n/opt/gitlab/embedded/service/gitlab-rails/lib/gitlab/sidekiq_middleware/correlation_logger.rb:9:in `call'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/middleware/chain.rb:130:in `block in invoke'\n/opt/gitlab/embedded/service/gitlab-rails/lib/gitlab/sidekiq_middleware/batch_loader.rb:7:in `call'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/middleware/chain.rb:130:in `block in invoke'\n/opt/gitlab/embedded/service/gitlab-rails/lib/gitlab/sidekiq_middleware/request_store_middleware.rb:8:in `call'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/middleware/chain.rb:130:in `block in invoke'\n/opt/gitlab/embedded/service/gitlab-rails/lib/gitlab/sidekiq_middleware/memory_killer.rb:18:in `call'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/middleware/chain.rb:130:in `block in invoke'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sentry-raven-2.9.0/lib/raven/integrations/sidekiq.rb:9:in `call'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/middleware/chain.rb:130:in `block in invoke'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/middleware/chain.rb:133:in `invoke'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:164:in `block in process'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:137:in `block (6 levels) in dispatch'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/job_retry.rb:109:in `local'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:136:in `block (5 levels) in dispatch'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/rails.rb:43:in `block in call'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/activesupport-5.1.7/lib/active_support/execution_wrapper.rb:85:in `wrap'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/activesupport-5.1.7/lib/active_support/reloader.rb:68:in `block in wrap'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/activesupport-5.1.7/lib/active_support/execution_wrapper.rb:85:in `wrap'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/activesupport-5.1.7/lib/active_support/reloader.rb:67:in `wrap'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/rails.rb:42:in `call'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:132:in `block (4 levels) in dispatch'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:250:in `stats'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:127:in `block (3 levels) in dispatch'\n/opt/gitlab/embedded/service/gitlab-rails/lib/gitlab/sidekiq_logging/structured_logger.rb:16:in `call'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:126:in `block (2 levels) in dispatch'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/job_retry.rb:74:in `global'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:125:in `block in dispatch'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/logging.rb:48:in `with_context'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/logging.rb:42:in `with_job_hash_context'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:124:in `dispatch'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:163:in `process'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:83:in `process_one'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:71:in `run'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/util.rb:16:in `watchdog'\n/opt/gitlab/embedded/lib/ruby/gems/2.6.0/gems/sidekiq-5.2.7/lib/sidekiq/util.rb:25:in `block in safe_thread'"}

@pyrmont
Copy link
Contributor

pyrmont commented Sep 16, 2019

Ta! Will start investigating!

@pyrmont
Copy link
Contributor

pyrmont commented Sep 16, 2019

@stanhu I think #1331 solves the problem. The issue looked to be caused by the fact that a certain combination of backslashes and a colon could cause a string to be incorrectly matched by one of the patterns in the :name state. (I believe this first occurred in v3.8.0 as a result of the change made by #1297.)

The fix was to include \\ in the class of escaped characters. This prevents the problematic strings from being matched in the :name state and instead causes them to be matched by the patterns in the :value state. These patterns are more permissive which means that they match more characters and avoid the situation that was causing the lexer to hang.

Let me know how it looks at your end.

@stanhu
Copy link
Contributor Author

stanhu commented Sep 16, 2019

@pyrmont That looks like it did the trick. Thanks for the quick fix!

@pyrmont
Copy link
Contributor

pyrmont commented Sep 16, 2019

@stanhu Great! We're currently on a two-week cadence for releases and the next one is due on Tuesday so this fix will roll out in v3.11.0. Sorry for the trouble! >_<

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bugfix-request A request for a bugfix to be developed.
Projects
None yet
Development

Successfully merging a pull request may close this issue.

2 participants