Upgrade to 7.1 throws exception on Azure AD login

[seb-bartholomew-amcs]

Hi there,

Had everything working fine with 7.0. Did upgrade to 7.1 and all appeared ok during this process.
Logging in using built-in/non-AD accounts works fine.

However, now when someone tries to login using Azure AD we get a 500 internal error when the browser redirects to /oauth2/callback/aad

Error in web logs are;

The FIRST time after a restart

2018.05.03 14:10:39 INFO web[][c.m.a.a.AuthenticationAuthority] [Correlation ID: 3c19029a-68ca...] Instance discovery was successful
2018.05.03 14:10:40 ERROR web[][o.s.s.p.w.RootFilter] Processing of request /oauth2/callback/aad?code=AQABA... failed
javax.servlet.ServletException: Filter execution threw an exception
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:200)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.sonar.server.user.UserSessionFilter.doFilter(UserSessionFilter.java:87)
at org.sonar.server.user.UserSessionFilter.doFilter(UserSessionFilter.java:71)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.sonar.server.platform.web.SecurityServletFilter.doHttpFilter(SecurityServletFilter.java:76)
at org.sonar.server.platform.web.SecurityServletFilter.doFilter(SecurityServletFilter.java:48)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.sonar.server.platform.web.RedirectFilter.doFilter(RedirectFilter.java:61)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.sonar.server.platform.web.requestid.RequestIdFilter.doFilter(RequestIdFilter.java:63)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.sonar.server.platform.web.RootFilter.doFilter(RootFilter.java:62)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.apache.catalina.filters.SetCharacterEncodingFilter.doFilter(SetCharacterEncodingFilter.java:108)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:199)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:140)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:81)
at ch.qos.logback.access.tomcat.LogbackValve.invoke(LogbackValve.java:256)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:342)
at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:803)
at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)
at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:868)
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1459)
at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.lang.Thread.run(Unknown Source)
Caused by: java.lang.NoClassDefFoundError: org/apache/log4j/Logger
at org.almrangers.auth.aad.JSONHelper.(JSONHelper.java:34)
at org.almrangers.auth.aad.AadIdentityProvider.getUserGroupsMembership(AadIdentityProvider.java:169)
at org.almrangers.auth.aad.AadIdentityProvider.callback(AadIdentityProvider.java:131)
at org.sonar.server.authentication.OAuth2CallbackFilter.handleOAuth2Provider(OAuth2CallbackFilter.java:96)
at org.sonar.server.authentication.OAuth2CallbackFilter.handleProvider(OAuth2CallbackFilter.java:76)
at org.sonar.server.authentication.OAuth2CallbackFilter.doFilter(OAuth2CallbackFilter.java:69)
at org.sonar.server.platform.web.MasterServletFilter$GodFilterChain.doFilter(MasterServletFilter.java:126)
at org.sonar.server.platform.web.MasterServletFilter.doFilter(MasterServletFilter.java:95)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
... 37 common frames omitted
Caused by: java.lang.ClassNotFoundException: org.apache.log4j.Logger
at org.sonar.classloader.ParentFirstStrategy.loadClass(ParentFirstStrategy.java:39)
at org.sonar.classloader.ClassRealm.loadClass(ClassRealm.java:87)
at org.sonar.classloader.ClassRealm.loadClass(ClassRealm.java:76)
... 46 common frames omitted

Subsequent Requests

2018.05.03 14:13:24 INFO web[][c.m.a.a.AuthenticationAuthority] [Correlation ID: 16bb4844-9...] Instance discovery was successful
2018.05.03 14:13:24 ERROR web[][o.s.s.p.w.RootFilter] Processing of request /oauth2/callback/aad?code=AQABAAIAAAD... failed
javax.servlet.ServletException: Filter execution threw an exception
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:200)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.sonar.server.user.UserSessionFilter.doFilter(UserSessionFilter.java:87)
at org.sonar.server.user.UserSessionFilter.doFilter(UserSessionFilter.java:71)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.sonar.server.platform.web.SecurityServletFilter.doHttpFilter(SecurityServletFilter.java:76)
at org.sonar.server.platform.web.SecurityServletFilter.doFilter(SecurityServletFilter.java:48)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.sonar.server.platform.web.RedirectFilter.doFilter(RedirectFilter.java:61)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.sonar.server.platform.web.requestid.RequestIdFilter.doFilter(RequestIdFilter.java:63)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.sonar.server.platform.web.RootFilter.doFilter(RootFilter.java:62)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.apache.catalina.filters.SetCharacterEncodingFilter.doFilter(SetCharacterEncodingFilter.java:108)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:199)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:140)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:81)
at ch.qos.logback.access.tomcat.LogbackValve.invoke(LogbackValve.java:256)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:342)
at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:803)
at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)
at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:868)
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1459)
at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.lang.Thread.run(Unknown Source)
Caused by: java.lang.NoClassDefFoundError: Could not initialize class org.almrangers.auth.aad.JSONHelper
at org.almrangers.auth.aad.AadIdentityProvider.getUserGroupsMembership(AadIdentityProvider.java:169)
at org.almrangers.auth.aad.AadIdentityProvider.callback(AadIdentityProvider.java:131)
at org.sonar.server.authentication.OAuth2CallbackFilter.handleOAuth2Provider(OAuth2CallbackFilter.java:96)
at org.sonar.server.authentication.OAuth2CallbackFilter.handleProvider(OAuth2CallbackFilter.java:76)
at org.sonar.server.authentication.OAuth2CallbackFilter.doFilter(OAuth2CallbackFilter.java:69)
at org.sonar.server.platform.web.MasterServletFilter$GodFilterChain.doFilter(MasterServletFilter.java:126)
at org.sonar.server.platform.web.MasterServletFilter.doFilter(MasterServletFilter.java:95)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
... 37 common frames omitted

Anyone else had this issue? Any ideas?

[arjanschaaf]

running into the exact same problem here....

[arjanschaaf]

@hkamel clearly the 1.1-rc1 release isn't working with Sonarqube 7.1. Any chance on a new release in the near future?

[mblaschke]

Have the same problem here

[srvrguy]

That's a very odd issue. Based on the message, it looks like SQ is not loading the plugin correctly.

If you're not using the group sync feature, can you drop back to the 1.0 version? Alternately, can you double-check that you're not loading multiple versions of the plugin and re-download the jar file from here, then copy it manually to the plugins directory, replacing any other copies?

[PSCNed]

Any news on this item? I think that this issue was solved in the code but never released.

[srvrguy]

I tried to reach out to @hkamel on Twitter but haven't heard back from him. Unfortunately, I don't think anyone who has write access is currently prepared to release an update. If you trust me, I can provide the updated copy I'm running on the SQ install where I work. (It has the changes from all my current PRs.)

Note that I'm not currently thinking about a hard fork. I'd much rather get the changes landed and not split a community.

[arjanschaaf]

@srvrguy see this comment by @julienlancelot: #53 (comment) You can ask to become a maintainer of this plugin, which would be a big help to a lot of customers of SonarQube...

[Vossekop]

@srvrguy if you don't become a maintainer of this plug-in and release an official version, i'd love to receive that private build you are working with. I would prefer not to have to set up a java build environment to create my build of this plug-in.

[srvrguy]

Thanks for the advice, @arjanschaaf. I've submitted a request for access.

@Vossekop You can download my custom build for now at https://1drv.ms/u/s!Ajm2ProaLajgkpQdsnpkSQYmi0DhBw

It will be removed once the important changes are merged into this repo. Please note that the build has the changes listed in #47, #50, #51, and #52

If you're updating SonarQube and run into issues with the 'users' table, you'll need to make some changes to the table. See my instructions that I'm going to be posting over in #55.

[Vossekop]

Very much appreciated @srvrguy i'll have a go at this tonight and see if I can get the upgrade to work this time.

[srvrguy]

If you have any problems, let me know and I'll try to help out.

[Vossekop]

Turned on the database upgrade last night, and just checked it this morning. Worked like a charm.

[hkamel]

@srvrguy apology for late reply. @Vossekop @arjanschaaf thank you for your support. I'm working with @srvrguy to release a version soon.

[tylersplitt]

@hkamel Not to be that guy, but how soon is soon? Very excited about this update!

[srvrguy]

It'll probably be within the next few weeks.

[hkamel]

@tylersplitt and @srvrguy we will try to push and intermediate major release (officially) during this week and we will keep updating with minor releases within next weeks.

Just FYI, the offical release cycle takes 2 days for the community to vote thorugh SonarSource community group.

[srvrguy]

You can update manually with the jar posted in the releases section once it's published.

If you need something now, you can use the link I posted above. Unless issues are found in the build I sent for testing, it should be identical to the official release, except the version number. (I've been running it successfully on SQ 7 for a while.)

[hkamel]

A new draft release has been published 1.1-RC2 the announcement has been sent to the official SonarSource community to kick the official release.

Thank you, everyone, for your contributions and @srvrguy big thank you for you great efforts and contributions

[jangrewe]

After hitting this issue with v1.0 of the plugin i restored the DB from a backup and updated the plugin to 1.1-RC2, but now i'm getting this:

[sonarqube-6879845bc9-drbzh] 2018.11.23 14:08:11 ERROR web[][o.s.s.p.d.m.DatabaseMigrationImpl] DB migration failed | time=10222ms 
[sonarqube-6879845bc9-drbzh] 2018.11.23 14:08:11 ERROR web[][o.s.s.p.d.m.DatabaseMigrationImpl] DB migration ended with an exception 
[sonarqube-6879845bc9-drbzh] org.sonar.server.platform.db.migration.step.MigrationStepExecutionException: Execution of migration step #2114 'Add unique indexes on table users' failed 
[sonarqube-6879845bc9-drbzh] at org.sonar.server.platform.db.migration.step.MigrationStepsExecutorImpl.execute(MigrationStepsExecutorImpl.java:79) 
[sonarqube-6879845bc9-drbzh] at org.sonar.server.platform.db.migration.step.MigrationStepsExecutorImpl.execute(MigrationStepsExecutorImpl.java:67) 
[sonarqube-6879845bc9-drbzh] at java.lang.Iterable.forEach(Iterable.java:75) 
[sonarqube-6879845bc9-drbzh] at org.sonar.server.platform.db.migration.step.MigrationStepsExecutorImpl.execute(MigrationStepsExecutorImpl.java:52) 
[sonarqube-6879845bc9-drbzh] at org.sonar.server.platform.db.migration.engine.MigrationEngineImpl.execute(MigrationEngineImpl.java:68) 
[sonarqube-6879845bc9-drbzh] at org.sonar.server.platform.db.migration.DatabaseMigrationImpl.doUpgradeDb(DatabaseMigrationImpl.java:105) 
[sonarqube-6879845bc9-drbzh] at org.sonar.server.platform.db.migration.DatabaseMigrationImpl.doDatabaseMigration(DatabaseMigrationImpl.java:80) 
[sonarqube-6879845bc9-drbzh] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) 
[sonarqube-6879845bc9-drbzh] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) 
[sonarqube-6879845bc9-drbzh] at java.lang.Thread.run(Thread.java:748) 
[sonarqube-6879845bc9-drbzh] Caused by: java.lang.IllegalStateException: Fail to execute CREATE UNIQUE INDEX uniq_external_id ON users (external_identity_provider, external_id) 
[sonarqube-6879845bc9-drbzh] at org.sonar.server.platform.db.migration.step.DdlChange$Context.execute(DdlChange.java:97) 
[sonarqube-6879845bc9-drbzh] at org.sonar.server.platform.db.migration.step.DdlChange$Context.execute(DdlChange.java:77) 
[sonarqube-6879845bc9-drbzh] at org.sonar.server.platform.db.migration.step.DdlChange$Context.execute(DdlChange.java:117) 
[sonarqube-6879845bc9-drbzh] at org.sonar.server.platform.db.migration.version.v72.AddUniqueIndexesOnUsers.execute(AddUniqueIndexesOnUsers.java:45) 
[sonarqube-6879845bc9-drbzh] at org.sonar.server.platform.db.migration.step.DdlChange.execute(DdlChange.java:45) 
[sonarqube-6879845bc9-drbzh] at org.sonar.server.platform.db.migration.step.MigrationStepsExecutorImpl.execute(MigrationStepsExecutorImpl.java:75) 
[sonarqube-6879845bc9-drbzh] ... 9 common frames omitted 
[sonarqube-6879845bc9-drbzh] Caused by: org.postgresql.util.PSQLException: ERROR: could not create unique index "uniq_external_id" 
[sonarqube-6879845bc9-drbzh] Detail: Key (external_identity_provider, external_id)=(aad, Azure AD) is duplicated. 
[sonarqube-6879845bc9-drbzh] at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2440) 
[sonarqube-6879845bc9-drbzh] at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2183) 
[sonarqube-6879845bc9-drbzh] at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:308) 
[sonarqube-6879845bc9-drbzh] at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:441) 
[sonarqube-6879845bc9-drbzh] at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:365) 
[sonarqube-6879845bc9-drbzh] at org.postgresql.jdbc.PgStatement.executeWithFlags(PgStatement.java:307) 
[sonarqube-6879845bc9-drbzh] at org.postgresql.jdbc.PgStatement.executeCachedSql(PgStatement.java:293) 
[sonarqube-6879845bc9-drbzh] at org.postgresql.jdbc.PgStatement.executeWithFlags(PgStatement.java:270) 
[sonarqube-6879845bc9-drbzh] at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:266) 
[sonarqube-6879845bc9-drbzh] at org.apache.commons.dbcp2.DelegatingStatement.execute(DelegatingStatement.java:175) 
[sonarqube-6879845bc9-drbzh] at org.apache.commons.dbcp2.DelegatingStatement.execute(DelegatingStatement.java:175) 
[sonarqube-6879845bc9-drbzh] at org.sonar.server.platform.db.migration.step.DdlChange$Context.execute(DdlChange.java:82) 
[sonarqube-6879845bc9-drbzh] ... 14 common frames omitted

This is with SQ 7.4, btw.

[tylersplitt]

Did you update the users table as described by @srvrguy in this thread? #55

[jangrewe]

Yes, after the first migration attempt. It changed 49 rows. Didn't fix that exception, though...

[srvrguy]

It looks like it's trying to use different columns than with the query I wrote for PostgreSQL. What DBMS are you using?

Also, if you browse the table, do you notice duplicates for the external_id column?

Note that if the upgrade fails, you need to restore from a db backup before you try again. SQ will not roll back any of the migrations that completed, and will fail on subsequent attempts.

[jangrewe]

Ah, that would explain why it's not working at all...

So now i set up a little lab environment with the dump from the production instance (7.0). I've started a 7.4 Docker image with 1.1-RC2 of the plugin, and when it gave me the message that the database needs to be upgraded, i tried to update the table before starting the upgrade, but:

sonar=# UPDATE users
sonar-# SET external_login = md5(random()::text)
sonar-# WHERE external_identity_provider = 'aad';
ERROR:  column "external_login" of relation "users" does not exist
LINE 2: SET external_login = md5(random()::text)

I had a another look at the table schema and noticed that there's indeed no external_login, but rather external_identity, so i ran this instead:

UPDATE users
SET external_identity = md5(random()::text)
WHERE external_identity_provider = 'aad';

... and then the migration finished successfully.