HTTPcontainer running in Kubernetes does not seem to pickup logging configuration changes?

rduivenvoorde commented 1 month ago

Context: after upgrading Frost images from 2.3.? to 2.4.0 the http server either does not show up, OR only after a long time. But the root page (in which I hoped to maybe have to be able to do some db update), does NOT show up. After a long time, the v1.1/xxx-endpoints eventually show up (but the / or databasestatus pages are still not available then).

The (INFO) logging of the server ends with:

07:43:04.205 INFO   d.f.i.ilt.frostserver.settings.Settings - Not set persistence.db.schemaPriority, using default value 'public'.
07:43:04.205 INFO     d.f.i.i.f.p.PersistenceManagerFactory - Running database update for de.fraunhofer.iosb.ilt.frostserver.persistence.pgjooq.PostgresPersistenceManager
07:43:04.207 INFO  d.f.i.i.f.p.p.PostgresPersistenceManager - Applying upgrades in liquibase/core.xml
07:43:04.207 INFO  d.f.i.i.f.p.pgjooq.utils.ConnectionUtils - Setting up BasicDataSource for database connections.
07:43:04.207 INFO   d.f.i.ilt.frostserver.settings.Settings - Setting persistence.db.driver has value 'org.postgresql.Driver'.
07:43:04.245 INFO   d.f.i.ilt.frostserver.settings.Settings - Setting persistence.db.username has value 'username'.
07:43:04.245 INFO   d.f.i.ilt.frostserver.settings.Settings - Setting persistence.db.password has value '*****'.
07:43:04.245 INFO   d.f.i.ilt.frostserver.settings.Settings - Setting persistence.db.conn.idle.max has value '10'.
07:43:04.250 INFO   d.f.i.ilt.frostserver.settings.Settings - Setting persistence.db.conn.max has value '10'.
07:43:04.251 INFO   d.f.i.ilt.frostserver.settings.Settings - Setting persistence.db.conn.idle.min has value '10'.
07:46:05.227 INFO                        liquibase.database - Set default schema name to k8s

I try to raise the logging level in the http container, but seem to fail

I do see debug messages in the mqtt container, but not in the http container

We have Frost-Server running in Kubernetes here. Using configuration in a values.yaml like the helm example: https://github.com/FraunhoferIOSB/FROST-Server/blob/v2.x/helm/frost-server/values.yaml

Added

  # Setting logging to DEBUG (instead of default=INFO)
  logging:
    default: DEBUG

or even

  # Setting logging to DEBUG (instead of default=INFO)
  logging:
    default: DEBUG
    parser: DEBUG
    queries: DEBUG
    requests: DEBUG
    service: DEBUG
    settings: DEBUG
    moquette: DEBUG
    liquibase: DEBUG
    jooq: DEBUG

I've also tried to add the LL_FROST env vars from https://fraunhoferiosb.github.io/FROST-Server/deployment/docker.html by putting FROST_LL in frost.envExtra key/value pairs

Going INTO the container, I do see FROST_LL with DEBUG values in env.

Any idea how to see what is going on?

Thanks for any pointer.

hylkevds commented 1 month ago

If that logging output is the last, then I suspect it's waiting to time-out trying to connect to your database.

rduivenvoorde commented 1 month ago

Mmm, I can reach the db from within the container (using curl). And I can connect using the same credentials from another machine (no psql in the container). Going to rollback to the older version to see what happens.

hylkevds commented 1 month ago

You could try setting the persistence.autoUpdateDatabase to false. That should allow FROST to complete its startup and may make debugging easier.

rduivenvoorde commented 1 month ago

Ok, set:

    db:
      autoUpdate: false

Then I have a web page again:

Some observations:

rolling back to 2.2 => all fine!
going to 2.3 => landing page ok, /v1.1/ works but /DatabaseStatus get's stuck on

09:55:22.078 DEBUG d.f.i.i.f.http.common.HttpRequestDecoder - Request: GET /FROST-Server/v1.1/ null
 - host -> frost.foo.nl
 - x-request-id -> 9c0c4e4c93c2c88ab12cc250cccf1db0
 - x-real-ip -> 10.42.172.1                                                                                                                                           
 - x-forwarded-for -> 10.42.172.1                                                                                                                                     
 - x-forwarded-host -> frost.foo.nl                                                                                                                       
 - x-forwarded-port -> 443                                                                                                                                            
 - x-forwarded-proto -> https                                                                                                                                         
 - x-forwarded-scheme -> https                                                                                                                                        
 - x-scheme -> https                                                                                                                                                  
 - user-agent -> Mozilla/5.0 (X11; Linux x86_64; rv:130.0) Gecko/20100101 Firefox/130.0                                                                               
 - accept -> text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/png,image/svg+xml,*/*;q=0.8
 - accept-language -> en-US,en;q=0.5                                                                                                                                  
 - accept-encoding -> gzip, deflate, br, zstd                                                                                                                         
 - upgrade-insecure-requests -> 1                                                                                                                                     
 - sec-fetch-dest -> document                                                                                                                                         
 - sec-fetch-mode -> navigate                                                                                                                                         
 - sec-fetch-site -> none                                                                                                                                             
 - sec-fetch-user -> ?1                                                                                                                                               
 - dnt -> 1                                                                                                                                                           
 - sec-gpc -> 1                                                                                                                                                       
 - priority -> u=0, i                                                                                                                                                 
 - pragma -> no-cache                                                                                                                                                 
 - cache-control -> no-cache                                                                                                                                          
 - cookie -> CID=BAAAAOjeA9JT6Baq81IvlDc4oFg=                                                                                                                         
09:55:46.759 INFO      d.f.i.i.f.http.common.DatabaseStatus - DatabaseStatus Servlet called.                                                                          
09:55:46.760 INFO  d.f.i.i.f.p.p.PostgresPersistenceManager - Checking for upgrades in liquibase/core.xml

same story for going to 2.4

So my conclusion for now: something in the db update is failing or not starting?

I'm on 2.4 now...

Looking in the database at the databasechangelog and databasechangeloglock table I now see:

id                                      |author|filename                                                         |dateexecuted           |orderexecuted|exectype|md5sum                            |description                                                                                                                                                                                                                                               |comments|tag|liquibase|contexts|labels|deployment_id|
----------------------------------------+------+-----------------------------------------------------------------+-----------------------+-------------+--------+----------------------------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+--------+---+---------+--------+------+-------------+
mdsPostgresTriggers.sql                 |scf   |liquibase/pluginmultidatastream/tables.xml                       |2024-09-24 09:35:38.552|           47|RERAN   |9:960ca4bf343bada5a5ceb3922731196a|sqlFile path=postgresTriggers.sql                                                                                                                                                                                                                         |        |   |4.28.0   |        |      |7170538504   |
postgresTriggers.sql                    |scf   |liquibase/plugincoremodel/tables.xml                             |2024-09-24 09:35:38.295|           46|RERAN   |9:de1cf7ab1748eabe4f49114d90e982ac|sqlFile path=postgresTriggers.sql                                                                                                                                                                                                                         |        |   |4.28.0   |        |      |7170538222   |
postgresFunctions.sql                   |scf   |liquibase/core.xml                                               |2024-09-24 09:35:37.666|           45|RERAN   |9:401ce1b4882bc13657787bf5cc74c5f7|sqlFile path=postgresFunctions.sql                                                                                                                                                                                                                        |        |   |4.28.0   |        |      |7170537543   |
2022-04-06-Index-OBS-MDS_ID-ID          |scf   |liquibase/pluginmultidatastream/foreignKeys.xml                  |2024-08-22 13:14:36.777|           43|EXECUTED|9:2f672323bae7d7074751d42c45fee6fb|createIndex indexName=OBS-MDS_ID-ID, tableName=OBSERVATIONS                                                                                                                                                                                               |        |   |4.28.0   |        |      |4332472390   |

and

id|locked|lockgranted|lockedby|
--+------+-----------+--------+
 1|false |           |        |

So it looks like 2.4 is running, but maybe with a not uptodate database?

rduivenvoorde commented 1 month ago

Ok... I get what the crux was. (though this was not shown in normal logs?)

Instead of via k8s I just started a fresh container using the same db and credentials:

we create a database with user 'sensorthings_owner'
we run the containers with user 'sensorthings_user' (setting the right permissions)

this is fine as long as nothing has to be changed in the db schema.

But on an update, liquibase wants to be the owner of the update functions:

11:48:44.153 [            main] INFO  d.f.i.i.f.p.PersistenceManagerFactory - Database-update-log:
Failed to upgrade database: Plugin.CoreModel.:
liquibase.exception.LiquibaseException: liquibase.exception.MigrationFailedException: Migration failed for changeset liquibase/plugincoremodel/tables.xml::postgresTriggers.sql::scf:
     Reason: liquibase.exception.DatabaseException: ERROR: must be owner of function datastreams_update_insert [Failed SQL: (0) -- Copyright (C) 2024 Fraunhofer Institut IOSB, Fraunhoferstr. 1, D 76131
-- Karlsruhe, Germany.

So I'll change (temporarily?) back to the owner of the db.

(OR is there an option to have 2 different users for this?)

hylkevds commented 1 month ago

Ok, good that you found out, but very strange that Liquibase did not throw any errors over this in the first log you posted!

Hmm, having a separate user for the liquibase commands is not a bad idea...

FraunhoferIOSB / FROST-Server

HTTPcontainer running in Kubernetes does not seem to pickup logging configuration changes? #2023