Feedback for Foreman 3.11 & Katello 4.13

Sorry for being late to the party, but finally had some time to test the RCs :slight_smile:

And I’m not sure what exactly happened yet, but it looks like the frontend can’t connect to Candlepin,
there are several pages not working (Subscription, Red Hat repository, Products, … pages showing either a white page or an Katello::Errors::CandlepinNotRunning error, Repository set page on the host detail page showing only a grey bar)

The only page that is still showing content normally is the sync_status page.

The upgrade process looked completely normal as well as the final repo upgrade worked without any issues.

In the production log, I see this error every few seconds:

2024-06-12T17:21:35 [E|app|81d25a51] Error occurred while starting Katello::CandlepinEventListener
2024-06-12T17:21:35 [E|app|81d25a51] Connection refused - connect(2) for "localhost" port 61613
2024-06-12T17:21:35 [E|app|81d25a51] /usr/share/gems/gems/stomp-1.4.10/lib/connection/netio.rb:461:in initialize
 81d25a51 | /usr/share/gems/gems/stomp-1.4.10/lib/connection/netio.rb:461:in open
 81d25a51 | /usr/share/gems/gems/stomp-1.4.10/lib/connection/netio.rb:461:in block in open_ssl_socket
 81d25a51 | /usr/share/ruby/timeout.rb:78:in timeout
 81d25a51 | /usr/share/gems/gems/stomp-1.4.10/lib/connection/netio.rb:460:in open_ssl_socket
 81d25a51 | /usr/share/gems/gems/stomp-1.4.10/lib/connection/netio.rb:520:in open_socket
 81d25a51 | /usr/share/gems/gems/stomp-1.4.10/lib/connection/utils.rb:116:in block in socket
 81d25a51 | /usr/share/gems/gems/stomp-1.4.10/lib/connection/utils.rb:109:in synchronize
 81d25a51 | /usr/share/gems/gems/stomp-1.4.10/lib/connection/utils.rb:109:in socket
 81d25a51 | /usr/share/gems/gems/stomp-1.4.10/lib/stomp/connection.rb:173:in initialize
 81d25a51 | /usr/share/gems/gems/stomp-1.4.10/lib/stomp/client.rb:134:in new
 81d25a51 | /usr/share/gems/gems/stomp-1.4.10/lib/stomp/client.rb:134:in create_connection
 81d25a51 | /usr/share/gems/gems/stomp-1.4.10/lib/stomp/client.rb:101:in block in initialize
 81d25a51 | /usr/share/ruby/timeout.rb:95:in block in timeout
 81d25a51 | /usr/share/ruby/timeout.rb:33:in block in catch
 81d25a51 | /usr/share/ruby/timeout.rb:33:in catch
 81d25a51 | /usr/share/ruby/timeout.rb:33:in catch
 81d25a51 | /usr/share/ruby/timeout.rb:110:in timeout
 81d25a51 | /usr/share/gems/gems/stomp-1.4.10/lib/stomp/client.rb:99:in initialize
 81d25a51 | /usr/share/gems/gems/katello-4.13.0.rc1/app/lib/katello/messaging/stomp_connection.rb:69:in new
 81d25a51 | /usr/share/gems/gems/katello-4.13.0.rc1/app/lib/katello/messaging/stomp_connection.rb:69:in client
 81d25a51 | /usr/share/gems/gems/katello-4.13.0.rc1/app/lib/katello/messaging/stomp_connection.rb:43:in subscribe
 81d25a51 | /usr/share/gems/gems/katello-4.13.0.rc1/app/services/katello/candlepin_event_listener.rb:34:in run
 81d25a51 | /usr/share/gems/gems/katello-4.13.0.rc1/app/lib/katello/event_daemon/monitor.rb:40:in block in check_services
 81d25a51 | /usr/share/gems/gems/katello-4.13.0.rc1/app/lib/katello/event_daemon/monitor.rb:30:in each
 81d25a51 | /usr/share/gems/gems/katello-4.13.0.rc1/app/lib/katello/event_daemon/monitor.rb:30:in check_services
 81d25a51 | /usr/share/gems/gems/katello-4.13.0.rc1/app/lib/katello/event_daemon/monitor.rb:16:in block (2 levels) in start
 81d25a51 | /usr/share/gems/gems/activesupport-6.1.7.7/lib/active_support/execution_wrapper.rb:87:in wrap
 81d25a51 | /usr/share/gems/gems/katello-4.13.0.rc1/app/lib/katello/event_daemon/monitor.rb:15:in block in start
 81d25a51 | /usr/share/gems/gems/katello-4.13.0.rc1/app/lib/katello/event_daemon/monitor.rb:14:in loop
 81d25a51 | /usr/share/gems/gems/katello-4.13.0.rc1/app/lib/katello/event_daemon/monitor.rb:14:in start
 81d25a51 | /usr/share/gems/gems/katello-4.13.0.rc1/app/lib/katello/event_daemon/runner.rb:84:in block (2 levels) in start_monitor_thread
 81d25a51 | /usr/share/gems/gems/activesupport-6.1.7.7/lib/active_support/execution_wrapper.rb:91:in wrap
 81d25a51 | /usr/share/gems/gems/katello-4.13.0.rc1/app/lib/katello/event_daemon/runner.rb:83:in block in start_monitor_thread
 81d25a51 | /usr/share/gems/gems/logging-2.3.1/lib/logging/diagnostic_context.rb:474:in block in create_with_logging_context

Another one I see is a repeating notification error:

2024-06-12T17:24:37 [I|app|12d98b0b] Started GET "/notification_recipients" for 10.27.12.2 at 2024-06-12 17:24:37 +0200
2024-06-12T17:24:37 [W|app|12d98b0b] 404 Not Found
 12d98b0b | /usr/share/gems/gems/rest-client-2.1.0/lib/restclient/abstract_response.rb:249:in exception_with_response
 12d98b0b | /usr/share/gems/gems/rest-client-2.1.0/lib/restclient/abstract_response.rb:129:in return!
 12d98b0b | /usr/share/gems/gems/rest-client-2.1.0/lib/restclient/request.rb:836:in process_result
 12d98b0b | /usr/share/gems/gems/rest-client-2.1.0/lib/restclient/request.rb:743:in block in transmit
 12d98b0b | /usr/share/ruby/net/http.rb:933:in start
 12d98b0b | /usr/share/gems/gems/rest-client-2.1.0/lib/restclient/request.rb:727:in transmit
 12d98b0b | /usr/share/gems/gems/rest-client-2.1.0/lib/restclient/request.rb:163:in execute
 12d98b0b | /usr/share/gems/gems/rest-client-2.1.0/lib/restclient/request.rb:63:in execute
 12d98b0b | /usr/share/gems/gems/rest-client-2.1.0/lib/restclient/resource.rb:51:in get
 12d98b0b | /usr/share/gems/gems/katello-4.13.0.rc1/app/models/katello/ping.rb:264:in backend_status
 12d98b0b | /usr/share/gems/gems/katello-4.13.0.rc1/app/models/katello/ping.rb:87:in block in ping_candlepin_without_auth
 12d98b0b | /usr/share/gems/gems/katello-4.13.0.rc1/app/models/katello/ping.rb:136:in exception_watch
 12d98b0b | /usr/share/gems/gems/katello-4.13.0.rc1/app/models/katello/ping.rb:86:in ping_candlepin_without_auth
 12d98b0b | /usr/share/gems/gems/katello-4.13.0.rc1/app/models/katello/ping.rb:236:in ping_services_for_capsule
 12d98b0b | /usr/share/gems/gems/katello-4.13.0.rc1/app/models/katello/ping.rb:24:in ping!
 12d98b0b | /usr/share/gems/gems/katello-4.13.0.rc1/app/services/katello/organization_creator.rb:20:in create_all_organizations!
 12d98b0b | /usr/share/gems/gems/katello-4.13.0.rc1/lib/katello/middleware/organization_created_enforcer.rb:12:in call
 12d98b0b | /usr/share/gems/gems/katello-4.13.0.rc1/lib/katello/middleware/event_daemon.rb:10:in call
 12d98b0b | /usr/share/gems/gems/actionpack-6.1.7.7/lib/action_dispatch/middleware/static.rb:24:in call
 12d98b0b | /usr/share/gems/gems/actionpack-6.1.7.7/lib/action_dispatch/middleware/static.rb:24:in call
 12d98b0b | /usr/share/gems/gems/apipie-dsl-2.6.2/lib/apipie_dsl/static_dispatcher.rb:67:in call
 12d98b0b | /usr/share/gems/gems/apipie-rails-1.3.0/lib/apipie/static_dispatcher.rb:74:in call
 12d98b0b | /usr/share/gems/gems/actionpack-6.1.7.7/lib/action_dispatch/middleware/static.rb:24:in call
 12d98b0b | /usr/share/gems/gems/actionpack-6.1.7.7/lib/action_dispatch/middleware/static.rb:24:in call
 12d98b0b | /usr/share/gems/gems/actionpack-6.1.7.7/lib/action_dispatch/middleware/static.rb:24:in call
 12d98b0b | /usr/share/gems/gems/actionpack-6.1.7.7/lib/action_dispatch/middleware/static.rb:24:in call
 12d98b0b | /usr/share/gems/gems/actionpack-6.1.7.7/lib/action_dispatch/middleware/static.rb:24:in call
 12d98b0b | /usr/share/gems/gems/actionpack-6.1.7.7/lib/action_dispatch/middleware/static.rb:24:in call
 12d98b0b | /usr/share/gems/gems/actionpack-6.1.7.7/lib/action_dispatch/middleware/static.rb:24:in call
 12d98b0b | /usr/share/gems/gems/actionpack-6.1.7.7/lib/action_dispatch/middleware/static.rb:24:in call
 12d98b0b | /usr/share/gems/gems/actionpack-6.1.7.7/lib/action_dispatch/middleware/static.rb:24:in call
 12d98b0b | /usr/share/foreman/lib/foreman/middleware/libvirt_connection_cleaner.rb:9:in call
 12d98b0b | /usr/share/foreman/lib/foreman/middleware/telemetry.rb:10:in call
 12d98b0b | /usr/share/gems/gems/apipie-rails-1.3.0/lib/apipie/middleware/checksum_in_headers.rb:27:in call
 12d98b0b | /usr/share/gems/gems/prometheus-client-4.2.2/lib/prometheus/middleware/exporter.rb:33:in call
 12d98b0b | /usr/share/gems/gems/rack-2.2.9/lib/rack/tempfile_reaper.rb:15:in call
 12d98b0b | /usr/share/gems/gems/rack-2.2.9/lib/rack/etag.rb:27:in call
 12d98b0b | /usr/share/gems/gems/rack-2.2.9/lib/rack/conditional_get.rb:27:in call
 12d98b0b | /usr/share/gems/gems/rack-2.2.9/lib/rack/head.rb:12:in call
 12d98b0b | /usr/share/gems/gems/actionpack-6.1.7.7/lib/action_dispatch/http/permissions_policy.rb:22:in call
 12d98b0b | /usr/share/gems/gems/actionpack-6.1.7.7/lib/action_dispatch/http/content_security_policy.rb:19:in call
 12d98b0b | /usr/share/foreman/lib/foreman/middleware/logging_context_session.rb:22:in call
 12d98b0b | /usr/share/gems/gems/rack-2.2.9/lib/rack/session/abstract/id.rb:266:in context
 12d98b0b | /usr/share/gems/gems/rack-2.2.9/lib/rack/session/abstract/id.rb:260:in call
 12d98b0b | /usr/share/gems/gems/actionpack-6.1.7.7/lib/action_dispatch/middleware/cookies.rb:697:in call
 12d98b0b | /usr/share/gems/gems/actionpack-6.1.7.7/lib/action_dispatch/middleware/callbacks.rb:27:in block in call
 12d98b0b | /usr/share/gems/gems/activesupport-6.1.7.7/lib/active_support/callbacks.rb:98:in run_callbacks
 12d98b0b | /usr/share/gems/gems/actionpack-6.1.7.7/lib/action_dispatch/middleware/callbacks.rb:26:in call
 12d98b0b | /usr/share/gems/gems/actionpack-6.1.7.7/lib/action_dispatch/middleware/actionable_exceptions.rb:18:in call
 12d98b0b | /usr/share/gems/gems/actionpack-6.1.7.7/lib/action_dispatch/middleware/debug_exceptions.rb:29:in call
 12d98b0b | /usr/share/gems/gems/actionpack-6.1.7.7/lib/action_dispatch/middleware/show_exceptions.rb:33:in call
 12d98b0b | /usr/share/gems/gems/railties-6.1.7.7/lib/rails/rack/logger.rb:37:in call_app
 12d98b0b | /usr/share/gems/gems/railties-6.1.7.7/lib/rails/rack/logger.rb:28:in call
 12d98b0b | /usr/share/gems/gems/sprockets-rails-3.4.2/lib/sprockets/rails/quiet_assets.rb:13:in call
 12d98b0b | /usr/share/foreman/lib/foreman/middleware/logging_context_request.rb:11:in call
 12d98b0b | /usr/share/gems/gems/actionpack-6.1.7.7/lib/action_dispatch/middleware/remote_ip.rb:81:in call
 12d98b0b | /usr/share/gems/gems/actionpack-6.1.7.7/lib/action_dispatch/middleware/request_id.rb:26:in call
 12d98b0b | /usr/share/gems/gems/katello-4.13.0.rc1/lib/katello/prevent_json_parsing.rb:12:in call
 12d98b0b | /usr/share/gems/gems/rack-2.2.9/lib/rack/method_override.rb:24:in call
 12d98b0b | /usr/share/gems/gems/rack-2.2.9/lib/rack/runtime.rb:22:in call
 12d98b0b | /usr/share/gems/gems/activesupport-6.1.7.7/lib/active_support/cache/strategy/local_cache_middleware.rb:29:in call
 12d98b0b | /usr/share/gems/gems/actionpack-6.1.7.7/lib/action_dispatch/middleware/executor.rb:14:in call
 12d98b0b | /usr/share/gems/gems/rack-2.2.9/lib/rack/sendfile.rb:110:in call
 12d98b0b | /usr/share/gems/gems/actionpack-6.1.7.7/lib/action_dispatch/middleware/ssl.rb:77:in call
 12d98b0b | /usr/share/gems/gems/actionpack-6.1.7.7/lib/action_dispatch/middleware/host_authorization.rb:142:in call
 12d98b0b | /usr/share/gems/gems/secure_headers-6.5.0/lib/secure_headers/middleware.rb:11:in call
 12d98b0b | /usr/share/gems/gems/railties-6.1.7.7/lib/rails/engine.rb:539:in call
 12d98b0b | /usr/share/gems/gems/railties-6.1.7.7/lib/rails/railtie.rb:207:in public_send
 12d98b0b | /usr/share/gems/gems/railties-6.1.7.7/lib/rails/railtie.rb:207:in method_missing
 12d98b0b | /usr/share/gems/gems/rack-2.2.9/lib/rack/urlmap.rb:74:in block in call
 12d98b0b | /usr/share/gems/gems/rack-2.2.9/lib/rack/urlmap.rb:58:in each
 12d98b0b | /usr/share/gems/gems/rack-2.2.9/lib/rack/urlmap.rb:58:in call
 12d98b0b | /usr/share/gems/gems/puma-6.4.2/lib/puma/configuration.rb:272:in call
 12d98b0b | /usr/share/gems/gems/puma-6.4.2/lib/puma/request.rb:100:in block in handle_request
 12d98b0b | /usr/share/gems/gems/puma-6.4.2/lib/puma/thread_pool.rb:378:in with_force_shutdown
 12d98b0b | /usr/share/gems/gems/puma-6.4.2/lib/puma/request.rb:99:in handle_request
 12d98b0b | /usr/share/gems/gems/puma-6.4.2/lib/puma/server.rb:464:in process_client
 12d98b0b | /usr/share/gems/gems/puma-6.4.2/lib/puma/server.rb:245:in block in run
 12d98b0b | /usr/share/gems/gems/puma-6.4.2/lib/puma/thread_pool.rb:155:in block in spawn_thread
 12d98b0b | /usr/share/gems/gems/logging-2.3.1/lib/logging/diagnostic_context.rb:474:in block in create_with_logging_context

Also checked if tomcat for candlepin is running and it looks like it does (though not without errors)

● tomcat.service - Apache Tomcat Web Application Container
   Loaded: loaded (/usr/lib/systemd/system/tomcat.service; enabled; vendor preset: disabled)
   Active: active (running) since Wed 2024-06-12 17:09:27 CEST; 17min ago
 Main PID: 1016 (java)
    Tasks: 38 (limit: 126422)
   Memory: 1017.3M
   CGroup: /system.slice/tomcat.service
           └─1016 /usr/lib/jvm/jre-17/bin/java -Xms1024m -Xmx4096m -Dcom.redhat.fips=false -Djava.security.auth.login.config=/usr/share/tomcat/conf/login.config -classpath /usr/share/tomcat/bin/bootstrap.jar:/usr/share/tomcat/bin/tomcat-juli.jar: -Dcatalina.base=/usr/share/tomcat -Dcatalina.home=/usr/share/tomcat -Djava.endorsed.dirs= -Djava.io.tmpdir=/var/cache/tomcat/temp -Djava.util.logging.config.file=/usr/share/tomcat/conf/logging.properties -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager org.apache.catalina.startup.Bootstrap start

Jun 12 17:09:59 r8-foreman-prod.fritz.box server[1016]:   Hint: Cast the output of the non-recursive term to the correct type.
Jun 12 17:09:59 r8-foreman-prod.fritz.box server[1016]:   Position: 655
Jun 12 17:09:59 r8-foreman-prod.fritz.box server[1016]: ERROR: Exception Primary Source: PostgreSQL 13.14
Jun 12 17:09:59 r8-foreman-prod.fritz.box server[1016]: 12-Jun-2024 17:09:59.356 INFO [main] liquibase.command.null Command execution complete
Jun 12 17:09:59 r8-foreman-prod.fritz.box server[1016]: 12-Jun-2024 17:09:59.360 SEVERE [main] org.apache.catalina.core.StandardContext.startInternal One or more listeners failed to start. Full details will be found in the appropriate container log file
Jun 12 17:09:59 r8-foreman-prod.fritz.box server[1016]: 12-Jun-2024 17:09:59.362 SEVERE [main] org.apache.catalina.core.StandardContext.startInternal Context [/candlepin] startup failed due to previous errors
Jun 12 17:09:59 r8-foreman-prod.fritz.box server[1016]: 12-Jun-2024 17:09:59.366 WARNING [main] org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesJdbc The web application [candlepin] registered the JDBC driver [org.postgresql.Driver] but failed to unregister it when the web application was stopped. To prevent a memory leak, the JDBC Driver has been forcibly unregistered.
Jun 12 17:09:59 r8-foreman-prod.fritz.box server[1016]: 12-Jun-2024 17:09:59.430 INFO [main] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory [/var/lib/tomcat/webapps/candlepin] has finished in [25,919] ms
Jun 12 17:09:59 r8-foreman-prod.fritz.box server[1016]: 12-Jun-2024 17:09:59.460 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler ["https-jsse-nio-127.0.0.1-23443"]
Jun 12 17:09:59 r8-foreman-prod.fritz.box server[1016]: 12-Jun-2024 17:09:59.671 INFO [main] org.apache.catalina.startup.Catalina.start Server startup in [26387] milliseconds

Foreman and Katello versions:
Foreman 3.10 → 3.11
Katello 4.12 → 4.13

Foreman and Proxy plugin versions:

foreman_tasks 9.1.1
foreman_ansible 14.0.0
foreman_bootdisk 21.2.3
foreman_puppet 6.3.0
foreman_remote_execution 13.1.0
foreman_snapshot_management 3.0.1
foreman_statistics 2.1.0
foreman_templates 9.4.0
foreman_ovirt 3.11.0
foreman_vmware 3.11.0

Distribution and version:

Rocky Linux 8.10

I will do a rollback to the snapshot before the upgrade now and try another time in the next days, maybe it was a intermittent fluke on my system.
But still wanted to report that back as the GA is coming closer.

Cheers, Lukas

Could you look at the journal of tomcat? I suspect it’s failing to migrate something, but need more info that’s probably in the journal.

Didn’t have as many time as I would have liked to, but here is the output of tomcat:

Jun 13 00:19:52 r8-foreman-prod.fritz.box systemd[1]: Started Apache Tomcat Web Application Container.
Jun 13 00:19:52 r8-foreman-prod.fritz.box server[12908]: Java virtual machine used: /usr/lib/jvm/jre-17/bin/java
Jun 13 00:19:52 r8-foreman-prod.fritz.box server[12908]: classpath used: /usr/share/tomcat/bin/bootstrap.jar:/usr/share/tomcat/bin/tomcat-juli.jar:
Jun 13 00:19:52 r8-foreman-prod.fritz.box server[12908]: main class used: org.apache.catalina.startup.Bootstrap
Jun 13 00:19:52 r8-foreman-prod.fritz.box server[12908]: flags used: -Xms1024m -Xmx4096m -Dcom.redhat.fips=false -Djava.security.auth.login.config=/usr/share/tomcat/conf/login.config
Jun 13 00:19:52 r8-foreman-prod.fritz.box server[12908]: options used: -Dcatalina.base=/usr/share/tomcat -Dcatalina.home=/usr/share/tomcat -Djava.endorsed.dirs= -Djava.io.tmpdir=/var/cache/tomcat/temp -Djava.util.logging.config.file=/usr/share/tomcat/conf/logging.properties -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager
Jun 13 00:19:52 r8-foreman-prod.fritz.box server[12908]: arguments used: start
Jun 13 00:19:52 r8-foreman-prod.fritz.box server[12908]: NOTE: Picked up JDK_JAVA_OPTIONS:  --add-opens=java.base/java.lang=ALL-UNNAMED --add-opens=java.base/java.io=ALL-UNNAMED --add-opens=java.base/java.util=ALL-UNNAMED --add-opens=java.base/java.util.concurrent=ALL-UNNAMED --add-opens=java.rmi/sun.rmi.transport=ALL-UNNAMED
Jun 13 00:19:53 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:19:53.543 INFO [main] org.apache.catalina.core.AprLifecycleListener.lifecycleEvent The Apache Tomcat Native library which allows using OpenSSL was not found on the java.library.path: [/usr/java/packages/lib:/usr/lib64:/lib64:/lib:/usr/lib]
Jun 13 00:19:54 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:19:54.054 INFO [main] org.apache.coyote.AbstractProtocol.init Initializing ProtocolHandler ["https-jsse-nio-127.0.0.1-23443"]
Jun 13 00:19:54 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:19:54.322 WARNING [main] org.apache.tomcat.util.net.SSLUtilBase.getEnabled Tomcat interprets the [ciphers] attribute in a manner consistent with the latest OpenSSL development branch. Some of the specified [ciphers] are not supported by the configured SSL engine for this connector (which may use JSSE or an older OpenSSL version) and have been skipped: [[TLS_ECDH_ECDSA_WITH_AES_256_GCM_SHA384, TLS_ECDH_RSA_WITH_AES_256_GCM_SHA384, TLS_ECDH_ECDSA_WITH_AES_128_GCM_SHA256, TLS_ECDH_RSA_WITH_AES_128_GCM_SHA256]]
Jun 13 00:19:54 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:19:54.877 INFO [main] org.apache.tomcat.util.net.AbstractEndpoint.logCertificate Connector [https-jsse-nio-127.0.0.1-23443], TLS virtual host [_default_], certificate type [UNDEFINED] configured from keystore [/etc/candlepin/certs/keystore] using alias [tomcat] with trust store [/etc/candlepin/certs/truststore]
Jun 13 00:19:54 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:19:54.947 INFO [main] org.apache.catalina.startup.Catalina.load Server initialization in [1751] milliseconds
Jun 13 00:19:55 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:19:55.008 INFO [main] org.apache.catalina.core.StandardService.startInternal Starting service [Catalina]
Jun 13 00:19:55 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:19:55.008 INFO [main] org.apache.catalina.core.StandardEngine.startInternal Starting Servlet engine: [Apache Tomcat/9.0.87]
Jun 13 00:19:55 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:19:55.027 INFO [main] org.apache.catalina.startup.HostConfig.deployDirectory Deploying web application directory [/var/lib/tomcat/webapps/candlepin]
Jun 13 00:20:01 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:01.176 INFO [main] org.apache.jasper.servlet.TldScanner.scanJars At least one JAR was scanned for TLDs yet contained no TLDs. Enable debug logging for this logger for a complete list of JARs that were scanned but no TLDs were found in them. Skipping unneeded JARs during scanning can improve startup time and JSP compilation time.
Jun 13 00:20:05 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:05.578 INFO [main] liquibase.database.null Set default schema name to public
Jun 13 00:20:05 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:05.631 INFO [main] liquibase.changelog.null Reading from public.databasechangelog
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.019 INFO [main] liquibase.lockservice.null Successfully acquired change log lock
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.021 INFO [main] liquibase.command.null Using deploymentId: 8230808021
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.023 INFO [main] liquibase.changelog.null Reading from public.databasechangelog
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: Running Changeset: db/changelog/20230725171517-add-anonymous-claimed_column.xml::20230725171517-1::sbakaj
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.156 INFO [main] liquibase.changelog.null Columns anonymous(boolean),claimed(boolean) added to cp_owner
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.157 INFO [main] liquibase.changelog.null ChangeSet db/changelog/20230725171517-add-anonymous-claimed_column.xml::20230725171517-1::sbakaj ran successfully in 7ms
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: Running Changeset: db/changelog/20230803000000-create-anonymous-consumers.xml::20230803000000-1::jalbrech
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.167 INFO [main] liquibase.snapshot.null Creating snapshot
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.301 INFO [main] liquibase.changelog.null Table cp_anonymous_cloud_consumers created
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.314 INFO [main] liquibase.changelog.null ChangeSet db/changelog/20230803000000-create-anonymous-consumers.xml::20230803000000-1::jalbrech ran successfully in 148ms
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: Running Changeset: db/changelog/20230803000000-create-anonymous-consumers.xml::20230803000000-2::jalbrech
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.332 INFO [main] liquibase.changelog.null Index cp_anonymous_cloud_consumers_idx1 created
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.338 INFO [main] liquibase.changelog.null Index cp_anonymous_cloud_consumers_idx2 created
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.339 INFO [main] liquibase.changelog.null ChangeSet db/changelog/20230803000000-create-anonymous-consumers.xml::20230803000000-2::jalbrech ran successfully in 19ms
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: Running Changeset: db/changelog/20230921144200-add_reg_auth_method_to_cp_consumers.xml::20230021144200-1::wpoteat
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.346 INFO [main] liquibase.changelog.null Columns reg_auth_method(VARCHAR(30)) added to cp_consumer
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.348 INFO [main] liquibase.changelog.null ChangeSet db/changelog/20230921144200-add_reg_auth_method_to_cp_consumers.xml::20230021144200-1::wpoteat ran successfully in 5ms
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: Running Changeset: db/changelog/202310040000000-create-anonymous-certificates.xml::202310040000000-1::jalbrech
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.355 INFO [main] liquibase.snapshot.null Creating snapshot
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.437 INFO [main] liquibase.changelog.null Table cp_anonymous_certificates created
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.440 INFO [main] liquibase.changelog.null Foreign key constraint added to cp_anonymous_cloud_consumers (cont_acc_cert_id)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.442 INFO [main] liquibase.changelog.null ChangeSet db/changelog/202310040000000-create-anonymous-certificates.xml::202310040000000-1::jalbrech ran successfully in 90ms
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: Running Changeset: db/changelog/202310040000000-create-anonymous-certificates.xml::202310040000000-2::jalbrech
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.457 INFO [main] liquibase.changelog.null Index cp_anonymous_certificates_idx1 created
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.458 INFO [main] liquibase.changelog.null ChangeSet db/changelog/202310040000000-create-anonymous-certificates.xml::202310040000000-2::jalbrech ran successfully in 12ms
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: Running Changeset: db/changelog/20231003113535-entity_layering_schema.xml::20231003113535-1::crog
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.467 INFO [main] liquibase.snapshot.null Creating snapshot
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.496 INFO [main] liquibase.changelog.null Table cp_contents created
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.502 INFO [main] liquibase.changelog.null Unique constraint added to cp_contents(namespace, content_id)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.505 INFO [main] liquibase.changelog.null Index cp_contents_idx1 created
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.509 INFO [main] liquibase.changelog.null Index cp_contents_idx2 created
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.510 INFO [main] liquibase.changelog.null ChangeSet db/changelog/20231003113535-entity_layering_schema.xml::20231003113535-1::crog ran successfully in 46ms
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: Running Changeset: db/changelog/20231003113535-entity_layering_schema.xml::20231003113535-2::crog
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.516 INFO [main] liquibase.snapshot.null Creating snapshot
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.537 INFO [main] liquibase.changelog.null Table cp_content_required_products created
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.540 INFO [main] liquibase.changelog.null Primary key added to cp_content_required_products (content_uuid, product_id)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.542 INFO [main] liquibase.changelog.null Foreign key constraint added to cp_content_required_products (content_uuid)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.544 INFO [main] liquibase.changelog.null ChangeSet db/changelog/20231003113535-entity_layering_schema.xml::20231003113535-2::crog ran successfully in 30ms
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: Running Changeset: db/changelog/20231003113535-entity_layering_schema.xml::20231003113535-3::crog
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.549 INFO [main] liquibase.snapshot.null Creating snapshot
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.567 INFO [main] liquibase.changelog.null Table cp_products created
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.571 INFO [main] liquibase.changelog.null Unique constraint added to cp_products(namespace, product_id)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.573 INFO [main] liquibase.changelog.null Index cp_products_idx1 created
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.575 INFO [main] liquibase.changelog.null Index cp_products_idx2 created
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.577 INFO [main] liquibase.changelog.null Foreign key constraint added to cp_products (derived_product_uuid)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.579 INFO [main] liquibase.changelog.null ChangeSet db/changelog/20231003113535-entity_layering_schema.xml::20231003113535-3::crog ran successfully in 32ms
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: Running Changeset: db/changelog/20231003113535-entity_layering_schema.xml::20231003113535-4::crog
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.584 INFO [main] liquibase.snapshot.null Creating snapshot
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.601 INFO [main] liquibase.changelog.null Table cp_product_attributes created
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.604 INFO [main] liquibase.changelog.null Primary key added to cp_product_attributes (product_uuid, name)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.606 INFO [main] liquibase.changelog.null Foreign key constraint added to cp_product_attributes (product_uuid)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.607 INFO [main] liquibase.changelog.null ChangeSet db/changelog/20231003113535-entity_layering_schema.xml::20231003113535-4::crog ran successfully in 25ms
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: Running Changeset: db/changelog/20231003113535-entity_layering_schema.xml::20231003113535-5::crog
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.612 INFO [main] liquibase.snapshot.null Creating snapshot
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.628 INFO [main] liquibase.changelog.null Table cp_product_dependent_products created
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.630 INFO [main] liquibase.changelog.null Primary key added to cp_product_dependent_products (product_uuid, product_id)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.632 INFO [main] liquibase.changelog.null Foreign key constraint added to cp_product_dependent_products (product_uuid)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.633 INFO [main] liquibase.changelog.null ChangeSet db/changelog/20231003113535-entity_layering_schema.xml::20231003113535-5::crog ran successfully in 23ms
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: Running Changeset: db/changelog/20231003113535-entity_layering_schema.xml::20231003113535-6::crog
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.638 INFO [main] liquibase.snapshot.null Creating snapshot
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.665 INFO [main] liquibase.changelog.null Table cp_product_provided_products created
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.667 INFO [main] liquibase.changelog.null Primary key added to cp_product_provided_products (product_uuid, provided_product_uuid)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.669 INFO [main] liquibase.changelog.null Foreign key constraint added to cp_product_provided_products (product_uuid)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.670 INFO [main] liquibase.changelog.null Foreign key constraint added to cp_product_provided_products (provided_product_uuid)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.671 INFO [main] liquibase.changelog.null ChangeSet db/changelog/20231003113535-entity_layering_schema.xml::20231003113535-6::crog ran successfully in 35ms
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: Running Changeset: db/changelog/20231003113535-entity_layering_schema.xml::20231003113535-7::crog
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.676 INFO [main] liquibase.snapshot.null Creating snapshot
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.691 INFO [main] liquibase.changelog.null Table cp_product_contents created
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.693 INFO [main] liquibase.changelog.null Foreign key constraint added to cp_product_contents (product_uuid)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.695 INFO [main] liquibase.changelog.null Foreign key constraint added to cp_product_contents (content_uuid)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.696 INFO [main] liquibase.changelog.null ChangeSet db/changelog/20231003113535-entity_layering_schema.xml::20231003113535-7::crog ran successfully in 22ms
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: Running Changeset: db/changelog/20231003113535-entity_layering_schema.xml::20231003113535-8::crog
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.701 INFO [main] liquibase.snapshot.null Creating snapshot
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.717 INFO [main] liquibase.changelog.null Table cp_product_branding created
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.719 INFO [main] liquibase.changelog.null Foreign key constraint added to cp_product_branding (product_uuid)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.720 INFO [main] liquibase.changelog.null ChangeSet db/changelog/20231003113535-entity_layering_schema.xml::20231003113535-8::crog ran successfully in 21ms
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: Running Changeset: db/changelog/20231003113535-entity_layering_schema.xml::20231003113535-9::crog
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.726 INFO [main] liquibase.snapshot.null Creating snapshot
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.744 INFO [main] liquibase.changelog.null Table cp_product_certificates created
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.746 INFO [main] liquibase.changelog.null Foreign key constraint added to cp_product_certificates (product_uuid)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.747 INFO [main] liquibase.changelog.null ChangeSet db/changelog/20231003113535-entity_layering_schema.xml::20231003113535-9::crog ran successfully in 23ms
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: Running Changeset: db/changelog/20231003113535-entity_layering_schema.xml::20231003113535-10::crog
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.860 INFO [main] liquibase.changelog.null Foreign key cp_pool_fk1 dropped
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.863 INFO [main] liquibase.changelog.null ChangeSet db/changelog/20231003113535-entity_layering_schema.xml::20231003113535-10::crog ran successfully in 114ms
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: Running Changeset: db/changelog/20231003113535-entity_layering_schema.xml::20231003113535-11::crog
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.919 WARNING [main] liquibase.executor.null table "tmp_active_global_products" does not exist, skipping
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.923 WARNING [main] liquibase.executor.null table "tmp_active_global_contents" does not exist, skipping
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.931 SEVERE [main] liquibase.changelog.null ChangeSet db/changelog/20231003113535-entity_layering_schema.xml::20231003113535-11::crog encountered an exception.
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:         liquibase.exception.DatabaseException: ERROR: recursive query "product_graph" column 1 has type character varying(32) in non-recursive term but type character varying overall
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:   Hint: Cast the output of the non-recursive term to the correct type.
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:   Position: 655 [Failed SQL: (0) -- Collect "active" global products and their children
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:             INSERT INTO tmp_active_global_products (uuid, pid, new_uuid, best)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 WITH RECURSIVE parent_child_map(parent_uuid, child_uuid) AS (
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                     SELECT uuid AS parent_uuid, derived_product_uuid AS child_uuid
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                         FROM cp2_products
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                         WHERE derived_product_uuid IS NOT NULL
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                     UNION
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                     SELECT product_uuid AS parent_uuid, provided_product_uuid AS child_uuid
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                         FROM cp2_product_provided_products),
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 product_graph(uuid, depth) AS (
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                     SELECT active.uuid, 0
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                         FROM cp2_products prod
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                         JOIN (SELECT product_uuid AS uuid FROM cp2_owner_products
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                             UNION
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                             SELECT product_uuid AS uuid FROM cp_pool) active ON active.uuid = prod.uuid
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                         WHERE prod.locked != 0
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                     UNION
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                     SELECT pcmap.child_uuid, pg.depth + 1
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                         FROM parent_child_map pcmap
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                         JOIN product_graph pg ON pg.uuid = pcmap.parent_uuid
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                         -- shouldn't be needed, but here just in case someone decided to be cheeky and define a
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                         -- cyclical product, or some other crazy thing that's entirely unsupported by CP's logic
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                         -- and queries
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                         WHERE pg.depth < 9)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 SELECT prod.uuid, prod.product_id, md5(concat('--global--', prod.product_id)) AS new_uuid, prod.uuid = best.uuid AS best_uuid
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                     FROM (SELECT DISTINCT uuid FROM product_graph) active
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                     JOIN cp2_products prod ON prod.uuid = active.uuid
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                     JOIN (SELECT prod2.product_id, MAX(prod2.uuid) AS uuid
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                         FROM product_graph pg1
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                         JOIN cp2_products prod2 ON prod2.uuid = pg1.uuid
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                         JOIN (SELECT prod3.product_id, MAX(prod3.updated) AS updated
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                             FROM product_graph pg2
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                             JOIN cp2_products prod3 ON prod3.uuid = pg2.uuid
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                             GROUP BY prod3.product_id) latest ON latest.product_id = prod2.product_id
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                         WHERE prod2.updated = latest.updated
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                         GROUP BY prod2.product_id) best ON best.product_id = prod.product_id]
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at liquibase.executor.jvm.JdbcExecutor$ExecuteStatementCallback.doInStatement(JdbcExecutor.java:470)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at liquibase.executor.jvm.JdbcExecutor.execute(JdbcExecutor.java:77)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at liquibase.executor.jvm.JdbcExecutor.execute(JdbcExecutor.java:179)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at liquibase.executor.AbstractExecutor.execute(AbstractExecutor.java:141)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at liquibase.database.AbstractJdbcDatabase.executeStatements(AbstractJdbcDatabase.java:1285)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at liquibase.changelog.ChangeSet.execute(ChangeSet.java:755)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at liquibase.changelog.visitor.UpdateVisitor.executeAcceptedChange(UpdateVisitor.java:119)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at liquibase.changelog.visitor.UpdateVisitor.visit(UpdateVisitor.java:68)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at liquibase.changelog.ChangeLogIterator$2.lambda$run$0(ChangeLogIterator.java:133)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at liquibase.Scope.lambda$child$0(Scope.java:186)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at liquibase.Scope.child(Scope.java:195)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at liquibase.Scope.child(Scope.java:185)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at liquibase.Scope.child(Scope.java:164)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at liquibase.changelog.ChangeLogIterator$2.run(ChangeLogIterator.java:122)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at liquibase.Scope.lambda$child$0(Scope.java:186)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at liquibase.Scope.child(Scope.java:195)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at liquibase.Scope.child(Scope.java:185)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at liquibase.Scope.child(Scope.java:164)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at liquibase.Scope.child(Scope.java:252)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at liquibase.Scope.child(Scope.java:256)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at liquibase.changelog.ChangeLogIterator.run(ChangeLogIterator.java:89)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at liquibase.command.core.AbstractUpdateCommandStep.lambda$run$0(AbstractUpdateCommandStep.java:110)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at liquibase.Scope.lambda$child$0(Scope.java:186)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at liquibase.Scope.child(Scope.java:195)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at liquibase.Scope.child(Scope.java:185)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at liquibase.Scope.child(Scope.java:164)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at liquibase.command.core.AbstractUpdateCommandStep.run(AbstractUpdateCommandStep.java:108)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at liquibase.command.core.UpdateCommandStep.run(UpdateCommandStep.java:105)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at liquibase.command.CommandScope.execute(CommandScope.java:217)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at org.candlepin.guice.CandlepinContextListener.executeUpdate(CandlepinContextListener.java:490)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at org.candlepin.guice.CandlepinContextListener.checkDbChangelog(CandlepinContextListener.java:466)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at org.candlepin.guice.CandlepinContextListener.contextInitialized(CandlepinContextListener.java:168)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at org.apache.catalina.core.StandardContext.listenerStart(StandardContext.java:4462)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:4914)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:171)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:683)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:658)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:661)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at org.apache.catalina.startup.HostConfig.deployDirectory(HostConfig.java:1175)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at org.apache.catalina.startup.HostConfig$DeployDirectory.run(HostConfig.java:1888)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at org.apache.tomcat.util.threads.InlineExecutorService.execute(InlineExecutorService.java:75)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at java.base/java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:123)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at org.apache.catalina.startup.HostConfig.deployDirectories(HostConfig.java:1086)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at org.apache.catalina.startup.HostConfig.deployApps(HostConfig.java:470)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at org.apache.catalina.startup.HostConfig.start(HostConfig.java:1584)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at org.apache.catalina.startup.HostConfig.lifecycleEvent(HostConfig.java:312)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at org.apache.catalina.util.LifecycleBase.fireLifecycleEvent(LifecycleBase.java:114)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at org.apache.catalina.util.LifecycleBase.setStateInternal(LifecycleBase.java:402)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at org.apache.catalina.util.LifecycleBase.setState(LifecycleBase.java:345)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at org.apache.catalina.core.ContainerBase.startInternal(ContainerBase.java:893)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at org.apache.catalina.core.StandardHost.startInternal(StandardHost.java:794)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:171)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1332)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1322)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at org.apache.tomcat.util.threads.InlineExecutorService.execute(InlineExecutorService.java:75)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at java.base/java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:145)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at org.apache.catalina.core.ContainerBase.startInternal(ContainerBase.java:866)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at org.apache.catalina.core.StandardEngine.startInternal(StandardEngine.java:248)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:171)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at org.apache.catalina.core.StandardService.startInternal(StandardService.java:433)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:171)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at org.apache.catalina.core.StandardServer.startInternal(StandardServer.java:925)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:171)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at org.apache.catalina.startup.Catalina.start(Catalina.java:735)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at java.base/java.lang.reflect.Method.invoke(Method.java:568)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at org.apache.catalina.startup.Bootstrap.start(Bootstrap.java:345)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:473)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:         Caused by: org.postgresql.util.PSQLException: ERROR: recursive query "product_graph" column 1 has type character varying(32) in non-recursive term but type character varying overall
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:   Hint: Cast the output of the non-recursive term to the correct type.
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:   Position: 655
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2725)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2412)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:371)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:502)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:419)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at org.postgresql.jdbc.PgStatement.executeWithFlags(PgStatement.java:341)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at org.postgresql.jdbc.PgStatement.executeCachedSql(PgStatement.java:326)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at org.postgresql.jdbc.PgStatement.executeWithFlags(PgStatement.java:302)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:297)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 at liquibase.executor.jvm.JdbcExecutor$ExecuteStatementCallback.doInStatement(JdbcExecutor.java:464)
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:                 ... 72 more
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: UPDATE SUMMARY
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: Run:                         26
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: Previously run:             611
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: Filtered out:               207
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: -------------------------------
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: Total change sets:          844
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: FILTERED CHANGE SETS SUMMARY
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: DBMS mismatch:              207
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.952 INFO [main] liquibase.util.null UPDATE SUMMARY
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.952 INFO [main] liquibase.util.null Run:                         26
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.952 INFO [main] liquibase.util.null Previously run:             611
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.952 INFO [main] liquibase.util.null Filtered out:               207
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.952 INFO [main] liquibase.util.null -------------------------------
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.952 INFO [main] liquibase.util.null Total change sets:          844
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.952 INFO [main] liquibase.util.null FILTERED CHANGE SETS SUMMARY
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.952 INFO [main] liquibase.util.null DBMS mismatch:              207
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.959 INFO [main] liquibase.util.null Update summary generated
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.964 INFO [main] liquibase.command.null Update command encountered an exception.
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.968 INFO [main] liquibase.lockservice.null Successfully released change log lock
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.969 INFO [main] liquibase.command.null Logging exception.
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: ERROR: Exception Details
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: ERROR: Exception Primary Class:  PSQLException
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: ERROR: Exception Primary Reason: ERROR: recursive query "product_graph" column 1 has type character varying(32) in non-recursive term but type character varying overall
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:   Hint: Cast the output of the non-recursive term to the correct type.
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]:   Position: 655
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: ERROR: Exception Primary Source: PostgreSQL 13.14
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.970 INFO [main] liquibase.command.null Command execution complete
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.972 SEVERE [main] org.apache.catalina.core.StandardContext.startInternal One or more listeners failed to start. Full details will be found in the appropriate container log file
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.974 SEVERE [main] org.apache.catalina.core.StandardContext.startInternal Context [/candlepin] startup failed due to previous errors
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.977 WARNING [main] org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesJdbc The web application [candlepin] registered the JDBC driver [org.postgresql.Driver] but failed to unregister it when the web application was stopped. To prevent a memory leak, the JDBC Driver has been forcibly unregistered.
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.986 INFO [main] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory [/var/lib/tomcat/webapps/candlepin] has finished in [13,959] ms
Jun 13 00:20:08 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:08.990 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler ["https-jsse-nio-127.0.0.1-23443"]
Jun 13 00:20:09 r8-foreman-prod.fritz.box server[12908]: 13-Jun-2024 00:20:09.032 INFO [main] org.apache.catalina.startup.Catalina.start Server startup in [14084] milliseconds

(this is my homelab prod system so I don’t mind the names showing up :+1: )

@nikos_moum Can you take a look at the traceback presented here?

Hi, would it be possible to get a copy of the affected DB, since we’re having trouble reproducing this?
Alternatively, if a DB copy isn’t possible, can we see the schema details (column sizes, etc.) from
SELECT *
FROM information_schema.columns
WHERE table_schema = ‘candlepin’;
?

Not publicly but sure will see that I get a copy of the whole PGSQL DB uploaded somewhere :+1:
that might take a while, it’s 21G ^^ (will send you a direct link, but if wanted I can also upload it somewhere, or dump a part of it (didn’t have to do that yes though, so guidance would be nice if needed))

I also tried the query, but didn’t find a table_schema of candlepin. So yeah hope the DB helps to find that.

1 Like

We’ve identified the problem and put in a fix for the issue in the underlying Candlepin component [1]. Once this gets through review and into a build, the Katello folks can provide guidance on when it’ll hit their end.

I’m still not quite sure how this didn’t get picked up by our migration testing, as nothing in the provided DB stood out as broken or abnormal, but it turns out that CTEs don’t retain the exact typing in all cases (our VARCHAR(32)s are becoming generic VARCHARs). While this is fine most of the time, the recursive union really doesn’t like this behavior when we use one CTE to build another, hence the error we see above.

[1] [M] CANDLEPIN-865: Added explicit casts in entity layering migration by Ceiu · Pull Request #4738 · candlepin/candlepin · GitHub

6 Likes

We’ll get Candlepin upgraded as soon as we can get our hands on a new release.

1 Like

I’ve just released candlepin 4.4.10 to the repos, which should have the fix.

@lumarel can you try the new build please?

4 Likes

I can confirm this fixes the upgrade issue!

Furthermore the only other thing I found up to now is, that I had to do a full cache reload to get the dashboard page to work again, beside that, everything looks to work as expected :+1:

5 Likes

Awesome, thanks for confirming!

@nikos_moum @Ceiu thank you for so promptly finding the fix and releasing it!

3 Likes