Troubleshooting Accounting Service - SSO

Contents


Whenever you need to change settings in the update win32.config/unix.config file you'll need to continue from the setup phase. Follow the environment specific upgrade instructions or see the guidelines in here:

Installation / upgrade incidents


Missing windows/unix.config settings


When:

  • Installing or upgrading SSO and executing the setup script

What:

  • Setup script complains about missing Accounting Service settings:

    error: required parameter is missing: accounting.instancename
    error: required parameter is missing: accounting.datasource.url
    error: required parameter is missing: accounting.jms.broker.port
    error: required parameter is missing: accounting.jms.broker.socket-timeout-ms

Why:

  • The necessary settings have not been added to or have been deleted from the configuration file win32.config/unix.config

How to fix:

  • Add the settings and modify the values according to your needs in win32.config/unix.config file as explained here and continue from the setup script again


JAVA_HOME not set


When:

  • Installing or upgrading SSO and executing install, update or remove script

What:

  • Script complains about missing Java:

    ./config/tomcat/install.sh
    Creating serverhost keystore /usr/local/ubisecure/ubilogin-sso/ubilogin/custom/tomcat/keystore.pfx
    Unable to find Java

Why:

  • JAVA_HOME environment variable has not been set but it is required by the Accounting Service with embedded scripts in the JAR file

How to fix:

  • Add JAVA_HOME as explained here and rerun the script

Accounting Service log file not found


When:

  • After upgrade when want to view the log events

What:

  • Log file is not found on the expected location

Why:

How to fix:

  • Fix the custom configuration file in this location: ubilogin/custom/accounting/config/application.yaml and update service by running ubilogin/config/tomcat/update script.

Incidents when starting


Database connection fails


When:

  • Starting Accounting Service for the first time after installation or restarting Accounting Service after a successful installation

What:

  • Database tables cannot be created in the initial startup or database connection cannot be created when checking the migration status, the following kind of error message in the Accounting Service application log:

    15:24:36.713 [main]       ERROR Application run failed : o.s.boot.SpringApplication.reportFailure
    org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'flyway' 
    defined in class path resource [org/springframework/boot/autoconfigure/flyway/FlywayAutoConfiguration
    ...
    Caused by: org.springframework.beans.BeanInstantiationException: Failed to instantiate [org.flywaydb.core.Flyway]:
    Factory method 'flyway' threw exception; nested exception is java.lang.IllegalStateException: 
    org.springframework.jdbc.support.MetaDataAccessException: Could not get Connection for extracting meta-data; nested exception is 
    org.springframework.jdbc.CannotGetJdbcConnectionException: Failed to obtain JDBC Connection; nested exception is 
    org.postgresql.util.PSQLException: FATAL: Ident authentication failed for user "accounting_user"

Why:

  • Cannot connect to the PostgreSQL Database

How to fix:

  • Check the root cause from the org.postgresql.util.PSQLException in the log, there are some alternatives:

org.postgresql.util.PSQLException: FATAL: no pg_hba.conf entry for host "127.0.0.1", 
user "accounting_user", database "accountingdb", SSL off
    • You have not configured PostgreSQL to accept connections from your host to the configured database and user, see the comment about md5 here and fix your PostgreSQL setup, start the Accounting Service again
    • You have forgotten to create the database in the PostgreSQL server, follow instructions in here, start the Accounting Service again
    • You have configured a wrong JDBC connection URL or username in the Accounting Service settings in win32.config/unix.config file, follow instructions in here (check that there are no trailing spaces in your settings)



org.postgresql.util.PSQLException: FATAL: Ident authentication failed for user "accounting_user"
    • You have not configured PostgreSQL to accept password based authentication, see the comment about md5 here and fix your PostgreSQL setup, start the Accounting Service again


org.postgresql.util.PSQLException: FATAL: password authentication failed for user "accounting_user"
    • You have configured a wrong JDBC connection password in the Accounting Service settings in win32.config/unix.config file, follow instructions in here, check especially that you don't have extra spaces or other invisible characters after the password setting
    • Note that if you have created a user name having uppercase letters these are converted to lowercase letters by PostgreSQL


org.postgresql.util.PSQLException: Connection to localhost:5432 refused. Check that the hostname and port 
are correct and that the postmaster is accepting TCP/IP connections.
    • Your PostgreSQL RDBMS server is down, start it, start the Accounting Service again
    • You have configured a wrong JDBC connection URL host name or port in the Accounting Service settings in win32.config/unix.config file, follow instructions in here
    • You cannot connect from the server SSO with Accounting Service is running to the correctly configured URL where the PostgreSQL RDBMS server is running, fix your network topology, firewall settings etc., start the Accounting Service again


org.postgresql.util.PSQLException: FATAL: the database system is starting up
    • Your PostgreSQL RDBMS server had not yet started when Accounting Service already tried to start, start the Accounting Service again when PostgreSQL server is up

Accessing secret key location fails


When:

  • Starting Accounting Service for the first time after installation or restarting Accounting Service after a successful installation

What:

Error starting ApplicationContext. To display the conditions report re-run your application with 'debug' enabled.
2019-08-24 04:47:59.510 ERROR 53308 --- [main] o.s.boot.SpringApplication               : Application run failed

org.springframework.beans.factory.UnsatisfiedDependencyException: Error creating bean with name 'ssoEventReceiver' defined in URL 
...
Error creating bean with name 'ubisecure.ids.accounting.security-com.ubisecure.ids.accounting.configuration.SecurityConfigurationProperties': 
Invocation of init method failed; nested exception is java.lang.IllegalArgumentException: 
Invalid value for 'ubisecure.ids.accounting.security.key-location-uri' ('secret-key-location')': 
file:////usr/local/ubisecure/ubilogin/sso/accounting/config/ids-accounting-service.secret
...
Caused by: java.io.IOException: Testing if file exists and is readable failed
        at com.ubisecure.ids.accounting.configuration.SecurityConfigurationProperties.init(SecurityConfigurationProperties.java:112)

Why:

How to fix:

  • Check the location from the stack trace
  • NOTE that correctly set file:///usr/local/... turns into file:////usr/local/... in the log.
Invalid value for 'ubisecure.ids.accounting.security.key-location-uri' ('secret-key-location')': 
file:////usr/local/ubisecure/ubilogin/sso/accounting/config/ids-accounting-service.secret
  • Check the root cause from the last causing exception in the stack trace, there are some alternatives
Caused by: java.io.IOException: Testing if file exists and is readable failed
    • You have configured a wrong security key location in the Accounting Service settings in win32.config/unix.config file, follow instructions in here
    • You have forgotten to set the key and put the file in place, create the file with a random key in it, start the Accounting Service again
Caused by: java.lang.IllegalArgumentException: URI has an authority component
    • When the location starts with file://usr/local/... it is not a proper file URI, turn into an absolute path by adding one / after the scheme, fix setting in the win32.config/unix.config file


Caused by: java.lang.IllegalArgumentException: Missing scheme
    • When the location starts with /usr/local/... it is not an URI, add the scheme file://, fix setting in the win32.config/unix.config file


File in secret key location is empty


When:

  • Starting Accounting Service for the first time after installation or restarting Accounting Service after a successful installation

What:

2019-08-29 15:03:44.965 ERROR 23028 --- [main] c.u.i.a.collector.DataProtector          : 
Invalid HMAC key in the key file: <secret key location>. Application will be stopped.
java.lang.IllegalArgumentException: Empty key

Why:

  • You have left the file in the secret key location empty

How to fix:

  • Generate a random key and store it into this file, start the Accounting Service again


Not enough permissions for the database user


When:

  • Starting Accounting Service for the first time after installation or restarting Accounting Service after a successful installation

What:

15:24:36.713 [main]       WARN ConfigServletWebServerApplicationContext : Exception encountered during context initialization - 
cancelling refresh attempt: org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'flywayInitializer' 
defined in class path resource [org/springframework/boot/autoconfigure/flyway/FlywayAutoConfiguration$FlywayConfiguration.class]: 
Invocation of init method failed; nested exception is org.flywaydb.core.internal.exception.FlywaySqlException:
Error while retrieving the list of applied migrations from Schema History table "public"."flyway_schema_history"
----------------------------------------------------------------------------------------------------------------
SQL State  : 42501
Error Code : 0
Message    : ERROR: permission denied for relation flyway_schema_history

Why:

  • Database user of the PostgreSQL Database does not have sufficient permissions to create tables and rows in the Accounting Service database
  • Permission to create tables is required by the Flyway migration tool

How to fix:

Incidents in operation


Proper SSO certificate not in place


When:

  • Accounting Service authorised user tries to access the browser end-points like https://accounting.example.com/accounting/report (example URL)
  • Browser redirects to the SSO login page where user is supposed to authenticate with the configured authentication method to the OAuth2 application created during the installation process

What:

  • Authentication succeeds but the report is not downloaded, there is this kind of [invalid_token_response] error page:

  • If the respective API end-point like https://accounting.example.com/api/v1/accounting/report is requested directly 401 is returned without any response data, the following kind of error message in the Accounting Service application log:
2019-11-13 15:06:47.677 ERROR 4100 --- [http-nio-8084-exec-10] c.u.i.a.oauth2.IntrospectingJwtDecoder   : 
Token: eyJjdHkiOiJKV1QiLCJhb...6Gfpp6GF877syj7OIo8oA introspection failed: ResourceAccessException:I/O error on 
POST request for "https://sso.example.com/uas/oauth2/introspection": sun.security.validator.ValidatorException: 
PKIX path building failed: sun.security.provider.certpath.SunCertPathBuilderException: unable to find valid certification path 
to requested target; nested exception is javax.net.ssl.SSLHandshakeException: sun.security.validator.ValidatorException: 
PKIX path building failed: sun.security.provider.certpath.SunCertPathBuilderException: unable to find valid certification path 
to requested target

Why:

  • Account Service can not complete the authentication flow as it does not trust SSO server when accessing it from server side
  • SSO server is not added to the Java trust store or the owner of the certificate is not correct
  • In the case above IP address has been used instead of the host name, which is not possible for the certificate subject

How to fix:

  • If the certificate is missing from the Java trust store, add it by following the instructions in here, and restart Accounting Service
  • If the host name in the certificate is not correct, fix settings in win32.config/unix.config file, remove the already created certificate from the installation directory before continuing with the installation


OAuth2 authorisation fails


When:

  • Authorised user tries to access the browser end-points like https://accounting.example.com/accounting/report (example URL)
  • Browser redirects to the SSO login page where user is supposed to authenticate with the configured authentication method to the OAuth2 application created during the installation process

What:

  • Authentication succeeds but SSO login page shows the following error message:
    Access to the requested resource is denied

Why:

How to fix:

  • Use a different user account or configure this user to be a member of Accounting Users in SSO


OAuth2 client authentication fails


When:

  • Authorised user tries to access the browser end-points like https://accounting.example.com/accounting/report (example URL)

What:

  • SSO login page shows the following error message:
    The requested application was not found

Why:

  • The OAuth2 client credentials in Accounting Service and the Accounting OAuth2 application in SSO do not match or the application in SSO has been deleted, see finalise Accounting Service installation about the Accounting application
  • The application and client credentials are automatically created and configured on both sides during SSO installation
  • Installation has not been properly executed or the related configuration has been manually changed afterwards

How to fix:

  • Install Ubisecure SSO and Accounting Service again

Redirect URI mismatch during OAuth2 flow


When:

  • Accounting Service authorised user tries to access the browser end-points like https://accounting.example.com/accounting/report (example URL)
  • Browser redirects to the SSO login page where user is supposed to authenticate with the configured authentication method to the OAuth2 application created during the installation process

What:

  • Authentication succeeds but the report is not downloaded, there is this kind of [invalid_redirect_uri_parameter] error page:

    or this kind of [Invalid credentials] error page:

Why:

  • Behind a proxy OAuth2 redirection requires a link to the proxy and not to the physical address of the machine hosting your application
    • The property name to define the log file location changed in SSO 8.7 and is now server.forward-headers-strategy which you may have missed when doing upgrade
  • Account Service redirect URI needs to be exactly the same in the browser and in the configuration
  • Browsers tend to change an uppercase hostname to lowercase and checking on Spring framework side is case sensitive

How to fix:

  • In case of proxy check that you have not overridden or removed server.forward-headers-strategy (earlier server.use-forward-headers) setting in Accounting Service additional configuration and configured your reverse proxy / load balancer to send X-Forwarded-For and X-Forwarded-Proto headers
    • Fix the custom configuration file in this location: ubilogin/custom/accounting/config/application.yaml and update service by running ubilogin/config/tomcat/update script.
  • Check that access URL (in lowercase) matches with accounting.url setting in win32.config/unix.config file, and that the network configuration supports this properly

Hostname changes during OAuth2 flow


When:

  • Accounting Service authorised user tries to access the browser end-points like https://accounting.example.com/accounting/report (example URL)
  • Browser redirects to the SSO login page where user is supposed to authenticate with the configured authentication method to the OAuth2 application created during the installation process

What:

  • Authentication succeeds but the report is not downloaded, there is this kind of [authorization_request_not_found] error page:

Why:

  • Account Service can not complete the authentication flow as the session cookie (JSESSIONID) has expired or does not have a matching hostname
  • Spring framework creates the session cookie with the hostname from the original request URL and tries to find the cookie with the hostname in the redirect URL and if they differ the problem occurs

How to fix:

  • Session expires by default in 10 minutes, try again if the error persists
  • Check that access URL matches with accounting.url setting in win32.config/unix.config file, and that the network configuration supports this properly


SSO server changes during OAuth2 flow


When:

  • Accounting Service authorised user tries to access the browser end-points like https://accounting.example.com/accounting/report (example URL)
  • Browser redirects to the SSO login page where user is supposed to authenticate with the configured authentication method to the OAuth2 application created during the installation process

What:

  • Authentication succeeds but the report is not downloaded, there is this kind of [invalid_grant] "Authorization code is not valid" error page:

Why:

  • In a clustered environment OAuth2 flow starts with one SSO server node but once SSO session is created the flow continues on another SSO server node which is not aware of the existing SSO session and rejects the authorization code
  • You must configure either active-passive setup or use Redis as session storage for your cluster

How to fix:

  • Fix clustered SSO configuration like explained here SSO Cluster installation
  • With IIS, check the SSO server load balancing and server affinity for sticky sessions, you need to have different client cookie name for different server farms, it is a good idea to restart your site after the configuration has been changed
  • As a temporary solution you can try several times and may succeed, or you can disable all but one SSO node in order to get the report you need. However, note that incorrect cluster configuration may also affect your customers in regular SSO usage.


Invalid CSV file contents


When:

  • Accounting Service authorised user tries to access the browser end-points like https://accounting.example.com/accounting/report (example URL)

What:

  • Authentication succeeds and a CSV file is returned but it is empty or contains an error message, when each CSV file should have at least a header row
  • Error example:

    <html>
      <head>
        <title>404 Not Found</title>
      </head>
      <body>
        <div>
          <h2>404 Not Found</h2>
        </div>
      </body>
    </html>

Why:

  • Accounting Service uses its own API to provide the actual result but accessing the API through the public address fails

How to fix:

Empty CSV file contents because Accounting certificate not in place


When:

  • Accounting Service authorised user tries to access the browser end-points like https://accounting.example.com/accounting/report (example URL)

What:

  • Authentication succeeds and a CSV file is returned but it is empty, when each CSV file should have at least a header row
  • There is a following kind of error message in the Accounting Service application log:

    2019-11-08 14:26:27.719 ERROR 24737 --- [http-nio-8442-exec-4] o.a.c.c.C.[.[.[/].[dispatcherServlet]    : Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception
    
    javax.net.ssl.SSLHandshakeException: General SSLEngine problem
        at sun.security.ssl.Handshaker.checkThrown(Handshaker.java:1521)
        at sun.security.ssl.SSLEngineImpl.checkTaskThrown(SSLEngineImpl.java:528)
        at sun.security.ssl.SSLEngineImpl.readNetRecord(SSLEngineImpl.java:802)
        at sun.security.ssl.SSLEngineImpl.unwrap(SSLEngineImpl.java:766)
        at javax.net.ssl.SSLEngine.unwrap(SSLEngine.java:624)
        at io.netty.handler.ssl.SslHandler$SslEngineType$3.unwrap(SslHandler.java:282)
        at io.netty.handler.ssl.SslHandler.unwrap(SslHandler.java:1329)
        at io.netty.handler.ssl.SslHandler.decodeJdkCompatible(SslHandler.java:1224)
        at io.netty.handler.ssl.SslHandler.decode(SslHandler.java:1271)
        at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:505)
        at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:444)
        at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:283)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:374)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:360)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:352)
        at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1421)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:374)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:360)
        at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:930)
        at io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:794)
        at io.netty.channel.epoll.AbstractEpollChannel$AbstractEpollUnsafe$1.run(AbstractEpollChannel.java:382)
        at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:163)
        at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:416)
        at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:331)
        at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:918)
        at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
        at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
        at java.lang.Thread.run(Thread.java:748)
    Caused by: javax.net.ssl.SSLHandshakeException: General SSLEngine problem
        at sun.security.ssl.Alerts.getSSLException(Alerts.java:192)
        at sun.security.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1709)
        at sun.security.ssl.Handshaker.fatalSE(Handshaker.java:318)
        at sun.security.ssl.Handshaker.fatalSE(Handshaker.java:310)
        at sun.security.ssl.ClientHandshaker.serverCertificate(ClientHandshaker.java:1639)
        at sun.security.ssl.ClientHandshaker.processMessage(ClientHandshaker.java:223)
        at sun.security.ssl.Handshaker.processLoop(Handshaker.java:1037)
        at sun.security.ssl.Handshaker$1.run(Handshaker.java:970)
        at sun.security.ssl.Handshaker$1.run(Handshaker.java:967)
        at java.security.AccessController.doPrivileged(Native Method)
        at sun.security.ssl.Handshaker$DelegatedTask.run(Handshaker.java:1459)
        at io.netty.handler.ssl.SslHandler.runAllDelegatedTasks(SslHandler.java:1499)
        at io.netty.handler.ssl.SslHandler.runDelegatedTasks(SslHandler.java:1513)
        at io.netty.handler.ssl.SslHandler.unwrap(SslHandler.java:1397)
        ... 21 common frames omitted
    Caused by: java.security.cert.CertificateException: No subject alternative DNS name matching accounting.ids-centos7.localdomain found.
        at sun.security.util.HostnameChecker.matchDNS(HostnameChecker.java:214)
        at sun.security.util.HostnameChecker.match(HostnameChecker.java:96)
        at sun.security.ssl.X509TrustManagerImpl.checkIdentity(X509TrustManagerImpl.java:462)
        at sun.security.ssl.X509TrustManagerImpl.checkIdentity(X509TrustManagerImpl.java:428)
        at sun.security.ssl.X509TrustManagerImpl.checkTrusted(X509TrustManagerImpl.java:261)
        at sun.security.ssl.X509TrustManagerImpl.checkServerTrusted(X509TrustManagerImpl.java:144)
        at sun.security.ssl.ClientHandshaker.serverCertificate(ClientHandshaker.java:1626)
        ... 30 common frames omitted
    
    
    

Why:

  • Accounting Service uses its own API to provide the actual result but accessing the API through the public address fails because of certificate with Accounting DNS name is not present: "No subject alternative DNS name matching accounting.ids-centos7.localdomain found"

How to fix:


Refreshing secret key fails


When:

  • Accounting Service is trying to initialise the secret key for pseudonymisation by reading it from the given location on the first 15 minutes of each month

What:

  • Refreshing secret key (HMAC key) fails, the following kind of error messages in the Accounting Service application log:

    2019-08-01 00:00:00.242 ERROR 416 --- [scheduling-1] c.u.i.a.collector.DataProtector          : 
    HMAC key could not be read from the key file and events cannot be stored. Service is not stopped but the system setup and 
    key file in location: <secret key location> should be checked and fixed. 
    java.nio.file.NoSuchFileException: <secret key file name>
    
    
    2019-08-01 00:00:00.691 ERROR 416 --- [scheduling-1] c.u.i.a.collector.DataProtector          : 
    Invalid HMAC key in the key file and events cannot be stored. Service is not stopped but the key file in 
    location: <secret key location> should be checked and fixed.
    java.lang.IllegalArgumentException: Empty key

Why:

  • The Accounting Service would not have started if you had a faulty key location or contents after the installation

  • You have accidentally either prevented access to the network resource or file, removed the file in the given location, or corrupted (emptied) its contents later, which is notified when the service tries to read the key again in the turn of the month

How to fix:

  • If the configured accounting.secret-key-location-uri is correct make the location available and have a random key present

  • The system will use the previous valid key up to the next time slot it tries to refresh the key

  • If you realise that accounting.secret-key-location-uri should be changed, fix setting in the win32.config/unix.config file

  • In normal case the job writes to the application log:

    2019-08-01 00:00:01.684  INFO 416 --- [scheduling-1] c.u.i.a.collector.DataProtector          : 
    Successfully initialised MAC provider with algorithm: HmacSHA256 and key of length: 32.


Database collision in the scheduled jobs


When:

  • In a clustered environment calculator or cleaner scheduler job is executing

What:

  • There are these kind of error messages in the Accounting Service application log on some of the nodes:

    Calculator job:
    2019-08-29 03:00:02.526  WARN 10644 --- [scheduling-1] c.u.i.a.calculator.AccountingCalculator  : 
    Failed to create Daily Accounting entities for day: 2019-08-28 because: 'could not execute statement; SQL [n/a]; 
    nested exception is org.hibernate.exception.LockAcquisitionException: could not execute statement'. 
    Check the 'calculationSchedule' configuration property for all running instances of this application.
    
    
    Cleaner job:
    2019-08-29 04:00:01.507 ERROR 15968 --- [scheduling-1] o.s.s.s.TaskUtils$LoggingErrorHandler    : Unexpected error occurred in scheduled task.
    org.springframework.orm.ObjectOptimisticLockingFailureException: Batch update returned unexpected row count from update [0]; 
    actual row count: 0; expected: 1; nested exception is...

Why:

  • You have forgotten to specify a different execution time for the scheduled jobs on different nodes

How to fix:

  • Check and fix calculation-schedule and cleaner-schedule on different nodes, follow instructions here, and restart Accounting Service
  • These warnings and errors are not critical as we never count daily events twice, and it does not matter if we try to delete something that is not existing anymore, but you get rid of unnecessary noise in the logs
  • When the jobs run normally they write to the application log:

    2019-08-29 03:00:00.162  INFO 82497 --- [scheduling-1] c.u.i.a.calculator.AccountingCalculator  : 
    Succesfully calculated Daily Accounting entities for day: 2019-08-28
    2019-08-29 04:00:00.226  INFO 9948 --- [scheduling-1] c.u.i.a.cleaner.DatabaseCleanerService   : 
    Succesfully cleaned Events and Daily Accounting entities created before date: 2019-01-29

SSO events are not recorded in the Accounting Service

You can verify that events are stored with the Accounting endpoint: /accounting/verify/events/<yyyy-mm-dd>. If the returned csv is empty the events are not stored or there can be an OAuth2 configuration error (a very rare situation).

Do the following on the SSO side

  1. Check from diagnostics logs if there are any warnings or errors, in particular the following ones. If you have followed the installation / upgrade process the broker URL host name should always be localhost and the port number should match with the one configured on the Accounting Service side.

    2019-05-03 16:48:18,707 init WARN Error in opening Accounting Service JMS connection in SSO startup. Accounting Service is a required component of SSO that needs to be functioning when running SSO.
    javax.jms.JMSException: Could not connect to broker URL: tcp://localhost:61616?connectionTimeout=10. Reason: java.net.SocketTimeoutException: connect timed out
    
    2019-05-03 17:00:08,112 tech WARN Error in opening Accounting Service JMS connection, event cannot be sent. Accounting Service is a required component of SSO that needs to be functioning when running SSO.
    javax.jms.JMSException: Could not connect to broker URL: tcp://localhost:61616?connectionTimeout=10. Reason: java.net.SocketTimeoutException: connect timed out
  2. Check from diagnostics logs if there is the following warning. It implies that you have not properly installed / upgraded SSO or the respective LDAP entry has been manually modified.

    2019-05-03 18:09:46,030 tech WARN MessageQueueSender missing Accounting Service broker URL. Accounting Service is a required component of SSO that needs to be functioning when running SSO.
  3. If the connection is in tact and the Accounting Service is running SSO diagnostics log shows in the startup

    2019-05-03 13:00:03,998 init MessageQueueSender initialised with connection to Accounting Service broker URL: tcp://localhost:36161?connectionTimeout
    =10
  4. If Accounting Service is not running start it.

  5. If connection timeout is too short on your server change the respective Accounting Service setting in win32.config/unix.config file, follow instructions in here. Remember to update LDAP.

  6. If the connection seems to be in tact change log level of uas/tech to DEBUG (see Management UI logging configuration) and check for the following messages in the diagnostics log. If the events are sent normally then the problem is on the Accounting Service receiving side.

    2019-08-14 12:43:35,969 tech DEBUG Going to send JMS message to the queue: SSOEventQueue
    2019-08-14 12:43:35,970 tech DEBUG Elapsed time in MessageQueueSender: 3377300 nanos (3 ms), enabled: true, message sent: true
  7. In the end remember to set the SSO log level back to INFO

Do the following on the Accounting Service side

  1. Check from the Accounting Service health check (see finalise Accounting Service installation) that all the system components are 'UP'. System can be running without being able to handle events properly if eventReceiver is 'DOWN', the details will show the problem cause. You can find more details about the error situation in the Accounting Service application log.
  2. Check from the Accounting Service application log if there are any warnings or errors especially related to listener execution from which you could derive the reason for failure. It might be related to a database connection or secret key handling incident explained on this page.

    2019-08-24 06:34:35.166  WARN 55025 --- [DefaultMessageListenerContainer-5] o.s.j.l.DefaultMessageListenerContainer  : Ex
    ecution of JMS message listener failed, and no ErrorHandler has been set.
    
    org.springframework.jms.listener.adapter.ListenerExecutionFailedException: Listener method 'public void com.ubisecure.ids
    .accounting.collector.SsoEventReceiver.receiveMessage(com.ubisecure.ids.accounting.event.SsoUserEvent)' threw exception;
  3. If the JMS message handling fails the Accounting Service retries again for a configured amount of times and finally you can see the following info and error messages. Look for other error messages near these messages and try to fix the problem.

    2019-08-24 06:34:35.196  INFO 55025 --- [DefaultMessageListenerContainer-4] c.u.i.a.collector.SsoEventReceiver       : Received message in Dead Letter Queue (DLQ) originated from: queue://SSOEventQueue
    ...
    2019-08-24 06:35:05.203 ERROR 55025 --- [DefaultMessageListenerContainer-4] c.u.i.a.collector.SsoEventReceiver       : Could not process the message in DLQ, setting event receiving down.
  4. If you cannot identify the problem change the logging level to DEBUG (see Accounting Service logging / Changing log level while system is running) and look for the following messages in the Accounting Service application log.  If you see only the first message then the problem lies with the pseudonymisation or database.

    2019-08-29 17:00:50.443 DEBUG 104774 --- [DefaultMessageListenerContainer-5] c.u.i.a.repository.EventDatabaseService  : Starting to create event of type: TICKET_GRANTED.
    2019-08-29 17:00:50.478 DEBUG 104774 --- [DefaultMessageListenerContainer-5] c.u.i.a.collector.SsoEventReceiver       : Successfully stored a new received event with key: 35
  5. You can set the logging level even to TRACE and look for the following pair of messages in the Accounting application log. If you don't see this log message the event sent by SSO has not for some reason reached Accounting JMS queue and you may need to look at the SSO side again. If you still don't see this message there can be a system error related to the JSM message conversion and you may contact Ubisecure support.

    2019-08-24 06:18:59.548 TRACE 55025 --- [DefaultMessageListenerContainer-3] c.u.i.a.collector.SsoEventReceiver       : Received event of type: TICKET_GRANTED
  6. In the end remember to set the Accounting Service log level back to INFO

Empty events CSV due OAuth2 cookie / configuration error

This is a rare situation that can happen during SSO upgrade e.g. if the Accounting Service has been tested in the browser but setup has been modified afterwards.

  1. Check from the Accounting Service audit log if there are these kind of lines with error "Access token is not active":

    "2019-09-18 12:59:05.131" "Resource access" "cn=Administrator,ou=System,cn=Ubilogin,dc=ucentos7allsingle" "GET /accounting/verify/events/2019-09-17" "SUCCESS" ""
    "2019-09-18 12:59:05.429" "Auth event" "" "GET /api/v1/accounting/verify/events/2019-09-17" "AUTHORIZATION_FAILURE" "OAuth2AuthenticationException: Access token is not active."
  2. SUCCESS in getting the resource indicates that there is a valid OAuth2 session but the AUTHORIZATION_FAILURE in token introspection indicates that OAuth2 client authentication fails.

  3. Client authentication settings in the browser cookie or Accounting Service settings do not match with the LDAP settings. Restart your browser and try again.

  4. If this does not help update SSO again
    in Linux:

    cd /usr/local/ubisecure/ubilogin-sso/ubilogin
    ./config/tomcat/update.sh

    in Windows:

    cd /d "C:\Program Files\Ubisecure\ubilogin-sso\ubilogin"
    config\tomcat\update.cmd

Sample health check in an error case

The following screen snapshot of Accounting Service health check is captured in a situation when the Accounting Service has first succesfully started but then PostgreSQL server has stopped. Processing the health check request takes 30 seconds which is the connection timeout length. HTTP response code 503 is returned with the following kind of JSON data: