Versions Compared

Key

  • This line was added.
  • This line was removed.
  • Formatting was changed.
Comment: Published by Scroll Versions from space IDS and version 8.7

...

Info
titleJAVA_HOME not set


When:

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

What:

  • Script complains about missing Java:

    Code Block
    languagetext
    ./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
Info
titleAccounting 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.

...

Info
titleDatabase 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:

    Code Block
    languagetext
    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:

Code Block
languagetext
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)



Code Block
languagetext
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


Code Block
languagetext
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


Code Block
languagetext
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


Code Block
languagetext
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
Info
titleAccessing secret key location fails


When:

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

What:

Code Block
languagetext
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.
Code Block
languagetext
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
Code Block
languagetext
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
Code Block
languagetext
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


Code Block
languagetext
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

...

Info
titleFile 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:

Code Block
languagetext
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

...

Info
titleNot 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:

Code Block
languagetext
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:

...

Info
titleProper 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:
Code Block
languagetext
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

...

Info
titleOAuth2 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

...

Info
titleOAuth2 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

...

Info
titleEmpty 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:

    Code Block
    languagetext
    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:

...

Info
titleRefreshing 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:

    Code Block
    languagetext
    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:

    Code Block
    languagetext
    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.

...

Info
titleDatabase 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:

    Code Block
    languagetext
    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:

    Code Block
    languagetext
    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

...

  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.

    Code Block
    languagetext
    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.

    Code Block
    languagetext
    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.

    Code Block
    languagetext
    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.

    Code Block
    languagetext
    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

...