Migration to 5.0 breaking LDAP and SAML login

olivierlambert · October 5, 2021, 8:36am

Hi,

Zammad 4.1.x on Debian 10 here Did an apt update, Zammad was updated to 5.0.

But then I couldn’t login anymore. Luckily, I did a VM snapshot first, so I reverted just before the update. I suspect the update is changing/breaking LDAP or SAML login.

I will create a local account to avoid being locked out, but since it’s an instance used “for real”, I won’t have a lot of time to fix it “live”.

Any idea or is it a known issue?

MrGeneration · October 5, 2021, 8:39am

You provided so much information that we know all now.
Honestly - with above information, what do you expect now?

olivierlambert · October 5, 2021, 8:40am

Well, if it’s a known issue (eg LDAP/SAML are broken after upgrade) then it’s enough to me

If it’s not, then I’ll try to find the root cause. That’s all I wanted to know.

edit: as I said “locked out”, it meant my credentials were rejected.

ado123 · October 5, 2021, 8:45am

Same Problem here. We updated via debian apt and afterwards it was not possible to login via ldap. No error message.
Then i reinstalled zammad and i get he folowing output

root@fritz:/var/cache/apt/archives# apt-get install --reinstall zammad
Paketlisten werden gelesen... Fertig
Abhängigkeitsbaum wird aufgebaut.       
Statusinformationen werden eingelesen.... Fertig
0 aktualisiert, 0 neu installiert, 1 erneut installiert, 0 zu entfernen und 0 nicht aktualisiert.
Es müssen 287 MB an Archiven heruntergeladen werden.
Nach dieser Operation werden 0 B Plattenplatz zusätzlich benutzt.
Holen:1 https://dl.packager.io/srv/deb/zammad/zammad/stable/debian 10/main amd64 zammad amd64 5.0.0-1633402025.d288b48b.buster [287 MB]
Es wurden 287 MB in 9 s geholt (31,9 MB/s).                                                                                                
(Lese Datenbank ... 102958 Dateien und Verzeichnisse sind derzeit installiert.)
Vorbereitung zum Entpacken von .../zammad_5.0.0-1633402025.d288b48b.buster_amd64.deb ...
Entpacken von zammad (5.0.0-1633402025.d288b48b.buster) über (5.0.0-1633402025.d288b48b.buster) ...
zammad (5.0.0-1633402025.d288b48b.buster) wird eingerichtet ...
# (Re)creating init scripts
Nothing to do.
Nothing to do.
Nothing to do.
# Enabling Zammad on boot
# Stopping Zammad
# database.yml found. Updating db...
/opt/zammad/vendor/ruby-2.7.4/lib/ruby/2.7.0/bundler/version.rb:4: warning: already initialized constant Bundler::VERSION
/usr/local/rvm/gems/ruby-2.6.8/gems/bundler-2.2.26/lib/bundler/version.rb:4: warning: previous definition of VERSION was here
/opt/zammad/vendor/ruby-2.7.4/lib/ruby/2.7.0/bundler/constants.rb:4: warning: already initialized constant Bundler::WINDOWS
/usr/local/rvm/gems/ruby-2.6.8/gems/bundler-2.2.26/lib/bundler/constants.rb:4: warning: previous definition of WINDOWS was here
/opt/zammad/vendor/ruby-2.7.4/lib/ruby/2.7.0/bundler/constants.rb:5: warning: already initialized constant Bundler::FREEBSD
/usr/local/rvm/gems/ruby-2.6.8/gems/bundler-2.2.26/lib/bundler/constants.rb:5: warning: previous definition of FREEBSD was here
/opt/zammad/vendor/ruby-2.7.4/lib/ruby/2.7.0/bundler/constants.rb:6: warning: already initialized constant Bundler::NULL
/usr/local/rvm/gems/ruby-2.6.8/gems/bundler-2.2.26/lib/bundler/constants.rb:6: warning: previous definition of NULL was here
/opt/zammad/vendor/ruby-2.7.4/lib/ruby/2.7.0/bundler/rubygems_integration.rb:8: warning: already initialized constant Bundler::RubygemsIntegration::EXT_LOCK
/usr/local/rvm/gems/ruby-2.6.8/gems/bundler-2.2.26/lib/bundler/rubygems_integration.rb:12: warning: previous definition of EXT_LOCK was here
/opt/zammad/vendor/ruby-2.7.4/lib/ruby/2.7.0/bundler/current_ruby.rb:12: warning: already initialized constant Bundler::CurrentRuby::KNOWN_MINOR_VERSIONS
/usr/local/rvm/gems/ruby-2.6.8/gems/bundler-2.2.26/lib/bundler/current_ruby.rb:12: warning: previous definition of KNOWN_MINOR_VERSIONS was here
/opt/zammad/vendor/ruby-2.7.4/lib/ruby/2.7.0/bundler/current_ruby.rb:25: warning: already initialized constant Bundler::CurrentRuby::KNOWN_MAJOR_VERSIONS
/usr/local/rvm/gems/ruby-2.6.8/gems/bundler-2.2.26/lib/bundler/current_ruby.rb:26: warning: previous definition of KNOWN_MAJOR_VERSIONS was here
/opt/zammad/vendor/ruby-2.7.4/lib/ruby/2.7.0/bundler/current_ruby.rb:27: warning: already initialized constant Bundler::CurrentRuby::KNOWN_PLATFORMS
/usr/local/rvm/gems/ruby-2.6.8/gems/bundler-2.2.26/lib/bundler/current_ruby.rb:28: warning: previous definition of KNOWN_PLATFORMS was here
/opt/zammad/vendor/ruby-2.7.4/lib/ruby/2.7.0/bundler/vendor/fileutils/lib/fileutils.rb:105: warning: already initialized constant Bundler::FileUtils::VERSION
/usr/local/rvm/gems/ruby-2.6.8/gems/bundler-2.2.26/lib/bundler/vendor/fileutils/lib/fileutils.rb:105: warning: previous definition of VERSION was here
/opt/zammad/vendor/ruby-2.7.4/lib/ruby/2.7.0/bundler/vendor/fileutils/lib/fileutils.rb:1284: warning: already initialized constant Bundler::FileUtils::Entry_::S_IF_DOOR
/usr/local/rvm/gems/ruby-2.6.8/gems/bundler-2.2.26/lib/bundler/vendor/fileutils/lib/fileutils.rb:1284: warning: previous definition of S_IF_DOOR was here
/opt/zammad/vendor/ruby-2.7.4/lib/ruby/2.7.0/bundler/vendor/fileutils/lib/fileutils.rb:1568: warning: already initialized constant Bundler::FileUtils::Entry_::DIRECTORY_TERM
/usr/local/rvm/gems/ruby-2.6.8/gems/bundler-2.2.26/lib/bundler/vendor/fileutils/lib/fileutils.rb:1568: warning: previous definition of DIRECTORY_TERM was here
/opt/zammad/vendor/ruby-2.7.4/lib/ruby/2.7.0/bundler/vendor/fileutils/lib/fileutils.rb:1626: warning: already initialized constant Bundler::FileUtils::OPT_TABLE
/usr/local/rvm/gems/ruby-2.6.8/gems/bundler-2.2.26/lib/bundler/vendor/fileutils/lib/fileutils.rb:1626: warning: previous definition of OPT_TABLE was here
/opt/zammad/vendor/ruby-2.7.4/lib/ruby/2.7.0/bundler/vendor/fileutils/lib/fileutils.rb:1685: warning: already initialized constant Bundler::FileUtils::LOW_METHODS
/usr/local/rvm/gems/ruby-2.6.8/gems/bundler-2.2.26/lib/bundler/vendor/fileutils/lib/fileutils.rb:1685: warning: previous definition of LOW_METHODS was here
/opt/zammad/vendor/ruby-2.7.4/lib/ruby/2.7.0/bundler/vendor/fileutils/lib/fileutils.rb:1692: warning: already initialized constant Bundler::FileUtils::METHODS
/usr/local/rvm/gems/ruby-2.6.8/gems/bundler-2.2.26/lib/bundler/vendor/fileutils/lib/fileutils.rb:1692: warning: previous definition of METHODS was here
rake aborted!
ArgumentError: Trying to register Bundler::GemfileError for status code 4 but Bundler::GemfileError is already registered
/opt/zammad/config/boot.rb:5:in `require'
/opt/zammad/config/boot.rb:5:in `<top (required)>'
/opt/zammad/config/application.rb:3:in `require_relative'
/opt/zammad/config/application.rb:3:in `<top (required)>'
/opt/zammad/Rakefile:7:in `require_relative'
/opt/zammad/Rakefile:7:in `<top (required)>'
/opt/zammad/vendor/bundle/ruby/2.7.0/gems/rake-13.0.6/exe/rake:27:in `<top (required)>'
/usr/local/rvm/gems/ruby-2.6.8/gems/bundler-2.2.26/lib/bundler/cli/exec.rb:58:in `load'
/usr/local/rvm/gems/ruby-2.6.8/gems/bundler-2.2.26/lib/bundler/cli/exec.rb:58:in `kernel_load'
/usr/local/rvm/gems/ruby-2.6.8/gems/bundler-2.2.26/lib/bundler/cli/exec.rb:23:in `run'
/usr/local/rvm/gems/ruby-2.6.8/gems/bundler-2.2.26/lib/bundler/cli.rb:477:in `exec'
/usr/local/rvm/gems/ruby-2.6.8/gems/bundler-2.2.26/lib/bundler/vendor/thor/lib/thor/command.rb:27:in `run'
/usr/local/rvm/gems/ruby-2.6.8/gems/bundler-2.2.26/lib/bundler/vendor/thor/lib/thor/invocation.rb:127:in `invoke_command'
/usr/local/rvm/gems/ruby-2.6.8/gems/bundler-2.2.26/lib/bundler/vendor/thor/lib/thor.rb:392:in `dispatch'
/usr/local/rvm/gems/ruby-2.6.8/gems/bundler-2.2.26/lib/bundler/cli.rb:31:in `dispatch'
/usr/local/rvm/gems/ruby-2.6.8/gems/bundler-2.2.26/lib/bundler/vendor/thor/lib/thor/base.rb:485:in `start'
/usr/local/rvm/gems/ruby-2.6.8/gems/bundler-2.2.26/lib/bundler/cli.rb:25:in `start'
/usr/local/rvm/gems/ruby-2.6.8/gems/bundler-2.2.26/exe/bundle:49:in `block in <top (required)>'
/usr/local/rvm/gems/ruby-2.6.8/gems/bundler-2.2.26/lib/bundler/friendly_errors.rb:128:in `with_friendly_errors'
/usr/local/rvm/gems/ruby-2.6.8/gems/bundler-2.2.26/exe/bundle:37:in `<top (required)>'
/opt/zammad/bin/bundle:5:in `load'
/opt/zammad/bin/bundle:5:in `<main>'
(See full trace by running task with --trace)
# Updating translations..

MrGeneration · October 5, 2021, 8:45am

You know the rules and so do I - provide your production log if you need help.

MrGeneration · October 5, 2021, 8:46am

Please help me to understand at which part the documentation should be improved or why I should continue to write it:
https://docs.zammad.org/en/latest/install/update.html

olivierlambert · October 5, 2021, 8:55am

I followed the doc instructions

Updating with a local account available give me a red login alert (to rule out LDAP/SSO right now):

PG::NotNullViolation: ERREUR: une valeur NULL viole la contrainte NOT NULL de la colonne « activity<u>stream</u>type_id » DETAIL: La ligne en échec contient (22099, null, null, null, null, 42, 42, 2021-10-05 08:53:20.523, 2021-10-05 08:53:20.525)

It’s in French but in plain English it should be something like:

PG::NotNullViolation: ERROR: a NULL value violates the NOT NULL constraintof the row "activity<u>stream</u>type_id" DETAIL: The failing line contains (22099, null, null, null, null, 42, 42, 2021-10-05 08:53:20.523, 2021-10-05 08:53:20.525)

I also tried to:

    systemctl stop zammad
    zammad run rails Cache.clear
    zammad run rake db:migrate
    systemctl start zammad

After the initial update, but same result.

Hope this helps. On my side, I’ll just wait a bit (probably tonight) to get more logs while doing tests. I might also clone the VM to do it.

ado123 · October 5, 2021, 9:22am

Sorry, I promise i will do better next time.
The relevant part of the production log is:
, [2021-10-05T10:54:57.972900 #2025-174280] INFO – : Processing by SessionsController#show as JSON
I, [2021-10-05T10:54:57.972955 #2025-174280] INFO – : Parameters: {“fingerprint”=>"-1840476201"}
E, [2021-10-05T10:54:57.992987 #2025-174280] ERROR – : PG::NotNullViolation: FEHLER: NULL-Wert in Spalte »activity_stream_type_id« verletz
t Not-Null-Constraint
DETAIL: Fehlgeschlagene Zeile enthält (52919, null, null, null, null, 622, 622, 2021-10-05 08:54:57.988244, 2021-10-05 08:54:57.991).
(ActiveRecord::NotNullViolation)
app/models/activity_stream.rb:82:in add' app/models/application_model/can_activity_stream_log.rb:46:in activity_stream_log’
app/controllers/sessions_controller.rb:228:in initiate_session_for' app/controllers/sessions_controller.rb:42:in show’
app/controllers/application_controller/has_download.rb:21:in block (4 levels) in <module:HasDownload>' app/controllers/application_controller/has_download.rb:20:in block (3 levels) in module:HasDownload’
app/controllers/application_controller/has_download.rb:19:in block (2 levels) in <module:HasDownload>' app/controllers/application_controller/handles_transitions.rb:16:in handle_transaction’
I, [2021-10-05T10:54:57.996424 #2025-174280] INFO – : Completed 422 Unprocessable Entity in 23ms (Views: 0.1ms | ActiveRecord: 3.6ms | All
ocations: 9800)

rolfschmidt · October 5, 2021, 9:23am

Hi @olivierlambert and @ado123 ,

can you try to run the following commands on your zammad run rails c to see what they return. Here an example of my dev system:

[1] pry(main)> TypeLookup.all
  TypeLookup Load (0.4ms)  SELECT "type_lookups".* FROM "type_lookups"
=> [#<TypeLookup:0x000055d043009768 id: 1, name: "session started", created_at: Mon, 04 Oct 2021 09:20:18 UTC +00:00, updated_at: Mon, 04 Oct 2021 09:20:18 UTC +00:00>,
 #<TypeLookup:0x000055d0430094c0 id: 2, name: "update", created_at: Mon, 04 Oct 2021 14:22:14 UTC +00:00, updated_at: Mon, 04 Oct 2021 14:22:14 UTC +00:00>,
 #<TypeLookup:0x000055d043009380 id: 3, name: "create", created_at: Mon, 04 Oct 2021 14:22:14 UTC +00:00, updated_at: Mon, 04 Oct 2021 14:22:14 UTC +00:00>]
[2] pry(main)> TypeLookup.by_name('update')
  TypeLookup Load (0.5ms)  SELECT "type_lookups".* FROM "type_lookups" WHERE "type_lookups"."name" = $1 LIMIT $2  [["name", "update"], ["LIMIT", 1]]
=> 2
[3] pry(main)> TypeLookup.by_name('create')
  TypeLookup Load (0.3ms)  SELECT "type_lookups".* FROM "type_lookups" WHERE "type_lookups"."name" = $1 LIMIT $2  [["name", "create"], ["LIMIT", 1]]
=> 3
[4] pry(main)> TypeLookup.by_name('session started')
  TypeLookup Load (0.6ms)  SELECT "type_lookups".* FROM "type_lookups" WHERE "type_lookups"."name" = $1 LIMIT $2  [["name", "session started"], ["LIMIT", 1]]
=> 1

ado123 · October 5, 2021, 9:26am

Hi, is this what you wanted ?

Loading production environment (Rails 6.0.4.1)
2.7.0 :001 > TypeLookup.all
 => #<ActiveRecord::Relation [#<TypeLookup id: 1, name: "session started", created_at: "2017-10-06 13:49:50", updated_at: "2017-10-06 13:49:50">, #<TypeLookup id: 2, name: "create", created_at: "2017-10-06 14:24:58", updated_at: "2017-10-06 14:24:58">, #<TypeLookup id: 3, name: "update", created_at: "2017-10-06 14:25:00", updated_at: "2017-10-06 14:25:00">, #<TypeLookup id: 4, name: "reminder_reached", created_at: "2017-10-27 06:00:11", updated_at: "2017-10-27 06:00:11">, #<TypeLookup id: 5, name: "switch to", created_at: "2017-11-17 13:24:44", updated_at: "2017-11-17 13:24:44">, #<TypeLookup id: 6, name: "ended switch to", created_at: "2017-11-17 13:25:13", updated_at: "2017-11-17 13:25:13">]> 
2.7.0 :002 > TypeLookup.by_name('update')
 => 3 
2.7.0 :003 > TypeLookup.by_name('create')
 => 2 
2.7.0 :004 > TypeLookup.by_name('session started')
 => nil 
2.7.0 :005 >

rolfschmidt · October 5, 2021, 9:28am

Hi @ado123 ,

weird it should return the id normally. Can you try to run Cache.clear again on your rails shell and try TypeLookup.by_name('session started') again? Does it really have no impact?

ado123 · October 5, 2021, 9:31am

After clear this is the output

2.7.0 :002 > TypeLookup.by_name('session started')
 => 1

rolfschmidt · October 5, 2021, 9:32am

can you login again?

ado123 · October 5, 2021, 9:36am

Yes, now i could run apt-get install --reinstall zammad without error and everything seems to work.

MrGeneration · October 5, 2021, 9:37am

I guess that was due to incorrect updating method.
Any way, I’m keen to learn how @olivierlambert instance is doing.

olivierlambert · October 5, 2021, 9:51am

Okay let me try that Back in few minutes to tell you the outcome

olivierlambert · October 5, 2021, 10:04am

So I did the steps but even with a apt-get install --reinstall zammad I got the:

Caused by:
PG::NotNullViolation: ERREUR:  une valeur NULL viole la contrainte NOT NULL de la colonne « activity_stream_type_id »

irb(main):001:0> TypeLookup.all
=> #<ActiveRecord::Relation [#<TypeLookup id: 1, name: "session started", created_at: "2020-12-15 10:39:04", updated_at: "2020-12-15 10:39:04">, #<TypeLookup id: 2, name: "create", created_at: "2020-12-15 10:43:39", updated_at: "2020-12-15 10:43:39">, #<TypeLookup id: 3, name: "update", created_at: "2020-12-15 10:43:39", updated_at: "2020-12-15 10:43:39">, #<TypeLookup id: 4, name: "switch to", created_at: "2020-12-15 10:50:27", updated_at: "2020-12-15 10:50:27">, #<TypeLookup id: 5, name: "ended switch to", created_at: "2020-12-15 10:50:54", updated_at: "2020-12-15 10:50:54">, #<TypeLookup id: 6, name: "escalation", created_at: "2020-12-15 13:50:47", updated_at: "2020-12-15 13:50:47">, #<TypeLookup id: 7, name: "escalation_warning", created_at: "2020-12-15 13:50:47", updated_at: "2020-12-15 13:50:47">, #<TypeLookup id: 8, name: "completed", created_at: "2021-02-10 21:24:33", updated_at: "2021-02-10 21:24:33">, #<TypeLookup id: 9, name: "reminder_reached", created_at: "2021-02-17 13:14:56", updated_at: "2021-02-17 13:14:56">]>
irb(main):002:0> TypeLookup.by_name('update')
=> nil
irb(main):003:0> TypeLookup.by_name('create')
=> 2
irb(main):004:0> TypeLookup.by_name('session started')
=> 1
irb(main):005:0> Cache.clear

However, after a BIG Cache.clear output, this time:

irb(main):006:0> TypeLookup.all
=> #<ActiveRecord::Relation [#<TypeLookup id: 1, name: "session started", created_at: "2020-12-15 10:39:04", updated_at: "2020-12-15 10:39:04">, #<TypeLookup id: 2, name: "create", created_at: "2020-12-15 10:43:39", updated_at: "2020-12-15 10:43:39">, #<TypeLookup id: 3, name: "update", created_at: "2020-12-15 10:43:39", updated_at: "2020-12-15 10:43:39">, #<TypeLookup id: 4, name: "switch to", created_at: "2020-12-15 10:50:27", updated_at: "2020-12-15 10:50:27">, #<TypeLookup id: 5, name: "ended switch to", created_at: "2020-12-15 10:50:54", updated_at: "2020-12-15 10:50:54">, #<TypeLookup id: 6, name: "escalation", created_at: "2020-12-15 13:50:47", updated_at: "2020-12-15 13:50:47">, #<TypeLookup id: 7, name: "escalation_warning", created_at: "2020-12-15 13:50:47", updated_at: "2020-12-15 13:50:47">, #<TypeLookup id: 8, name: "completed", created_at: "2021-02-10 21:24:33", updated_at: "2021-02-10 21:24:33">, #<TypeLookup id: 9, name: "reminder_reached", created_at: "2021-02-17 13:14:56", updated_at: "2021-02-17 13:14:56">]>
irb(main):007:0> TypeLookup.by_name('update')
=> 3
irb(main):008:0> TypeLookup.by_name('create')
=> 2
irb(main):009:0> TypeLookup.by_name('session started')
=> 1

Now it worked! Without reinstall, instantly. So clearly, Cache.clear in the CLI fixed it.

olivierlambert · October 5, 2021, 10:06am

However, the Dashboard is broken (error in the browser console, like App.n(error) | executeSingel task: Dashboard ReferenceError: item is not defined).

Should I reboot?

olivierlambert · October 5, 2021, 10:13am

@ado123 can you access the Dashboard?

I can’t access it:

App.n(error)                   | executeSingel task: Dashboard ReferenceError: item is not defined
    this.JST["app/views/dashboard/activity_stream_item"]/</< https://myURL.fr/assets/application-c89a4b0492e6b805dc3cd202300f32ff5748db169bff72b0b69f339bc31adba0.js:62
    this.JST["app/views/dashboard/activity_stream_item"]/< https://myURL.fr/assets/application-c89a4b0492e6b805dc3cd202300f32ff5748db169bff72b0b69f339bc31adba0.js:62
    "app/views/dashboard/activity_stream_item" https://myURL.fr/assets/application-c89a4b0492e6b805dc3cd202300f32ff5748db169bff72b0b69f339bc31adba0.js:62
    view https://myURL.fr/assets/application-c89a4b0492e6b805dc3cd202300f32ff5748db169bff72b0b69f339bc31adba0.js:22
    renderItem https://myURL.fr/assets/application-c89a4b0492e6b805dc3cd202300f32ff5748db169bff72b0b69f339bc31adba0.js:27
    s https://myURL.fr/assets/application-c89a4b0492e6b805dc3cd202300f32ff5748db169bff72b0b69f339bc31adba0.js:27
    renderAll https://myURL.fr/assets/application-c89a4b0492e6b805dc3cd202300f32ff5748db169bff72b0b69f339bc31adba0.js:27
    s https://myURL.fr/assets/
[...]

edit: SSO with SAML works, but not the LDAP login anymore. Internal user is OK

olivierlambert · October 5, 2021, 10:18am

Okay got it WORKING!!!

I had to do the apt-get install --reinstall zammad after the Cache.clear otherwise the database migration wasn’t complete.

Thanks @ado123 @MrGeneration and @rolfschmidt