Unit Test Report

[x]

        
ft1.6: tests.unit.test_static_driver.TestStaticDriver.test_static_deregistration_in_usetesttools.testresult.real._StringException: dburi: {{{mariadb+pymysql://DWJwsoyk_8564:c830e236b9ce4e14815a263aff4a0c9f@127.0.0.1:3306/DWJwsoyk_8564}}}
logging: {{{
2025-10-28 15:33:08,612 zuul.test.MySQLSchemaFixture     DEBUG    Creating database 127.0.0.1:3306:DWJwsoyk_8564
2025-10-28 15:33:08,620 git.util                         DEBUG    sys.platform='linux', git_executable='git'
2025-10-28 15:33:08,628 git.util                         DEBUG    sys.platform='linux', git_executable='git'
2025-10-28 15:33:08,640 git.util                         DEBUG    sys.platform='linux', git_executable='git'
2025-10-28 15:33:08,647 git.util                         DEBUG    sys.platform='linux', git_executable='git'
2025-10-28 15:33:08,666 zuul.zk.base.ZooKeeperClient     DEBUG    ZooKeeper connection (session: 0x10000076ee72063): CONNECTED
2025-10-28 15:33:08,670 zuul.KeyStorage                  INFO     Created key at /keystorage2/tenant/tenant-one/ssh
2025-10-28 15:33:08,674 zuul.KeyStorage                  INFO     Created key at /keystorage/gerrit/org/org%2Fcommon-config/secrets
2025-10-28 15:33:08,674 zuul.KeyStorage                  INFO     Created key at /keystorage/gerrit/org/org%2Fcommon-config/ssh
2025-10-28 15:33:08,676 zuul.KeyStorage                  INFO     Created key at /keystorage/gerrit/org/org%2Fproject/secrets
2025-10-28 15:33:08,676 zuul.KeyStorage                  INFO     Created key at /keystorage/gerrit/org/org%2Fproject/ssh
2025-10-28 15:33:08,676 zuul.TimerDriver                 DEBUG    Starting apscheduler
2025-10-28 15:33:08,676 apscheduler.scheduler            INFO     Scheduler started
2025-10-28 15:33:08,677 apscheduler.scheduler            DEBUG    Looking for jobs to run
2025-10-28 15:33:08,677 apscheduler.scheduler            DEBUG    No jobs; waiting until a job is added
2025-10-28 15:33:08,677 Zuul.CapabilitiesRegistry        DEBUG    Capabilities "job_history" updated
2025-10-28 15:33:08,677 zuul.BubblewrapDriver            DEBUG    Initializing bubblewrap with oom_score_adj starting: 0, final: 200
2025-10-28 15:33:08,678 zuul.BubblewrapExecutionContext  DEBUG    Bubblewrap command: setpriv --ambient-caps -all choom -n 200 -- bwrap --dir /tmp --tmpfs /tmp --dir /var --dir /var/tmp --dir /run/user/1000 --ro-bind /usr /usr --ro-bind /lib /lib --ro-bind /bin /bin --ro-bind /sbin /sbin --ro-bind /etc/ld.so.cache /etc/ld.so.cache --ro-bind /etc/resolv.conf /etc/resolv.conf --ro-bind /etc/hosts /etc/hosts --ro-bind /etc/localtime /etc/localtime --ro-bind /dev/null /dev/null --bind /tmp /tmp --tmpfs /tmp/tmp --proc /proc --dev /dev --chdir /tmp --unshare-all --share-net --die-with-parent --uid 1000 --gid 1000 --file 29 /etc/passwd --file 31 /etc/group --ro-bind /lib64 /lib64 --ro-bind /etc/nsswitch.conf /etc/nsswitch.conf --ro-bind /etc/alternatives /etc/alternatives --ro-bind /etc/ssl/certs /etc/ssl/certs --ro-bind /etc/subuid /etc/subuid
2025-10-28 15:33:08,686 zuul.github.graphql              DEBUG    Loading prepared graphql queries
2025-10-28 15:33:08,686 zuul.test.FakeGithubClientManager INFO     Authing to GitHub
2025-10-28 15:33:08,688 zuul.ExecutorQueue               DEBUG    Creating executor queue at root /zuul/executor/unzoned
2025-10-28 15:33:08,695 zuul.zk.ZooKeeper                DEBUG    Initialize cache at /zuul/executor/unzoned
2025-10-28 15:33:08,698 zuul.zk.ZooKeeper                DEBUG    Cache at /zuul/executor/unzoned is ready
2025-10-28 15:33:08,704 zuul.zk.ZooKeeper                DEBUG    Initialize cache at /zuul/merger
2025-10-28 15:33:08,707 zuul.zk.ZooKeeper                DEBUG    Cache at /zuul/merger is ready
2025-10-28 15:33:08,707 opentelemetry.trace              WARNING  Overriding of current TracerProvider is not allowed
2025-10-28 15:33:08,714 zuul.zk.base.ZooKeeperClient     DEBUG    ZooKeeper connection (session: 0x10000076ee72064): CONNECTED
2025-10-28 15:33:08,716 zuul.zk.ZooKeeper                DEBUG    Initialize cache at /zuul/merger
2025-10-28 15:33:08,719 zuul.zk.ZooKeeper                DEBUG    Cache at /zuul/merger is ready
2025-10-28 15:33:08,720 zuul.zk.ZooKeeper                DEBUG    Initialize cache at /keystorage-oidc
2025-10-28 15:33:08,721 zuul.zk.ZooKeeper                DEBUG    Cache at /keystorage-oidc is ready
2025-10-28 15:33:08,721 zuul.Component                   INFO     Registering component in ZooKeeper /zuul/components/executor/np6bc1754cc6fe4
2025-10-28 15:33:08,724 zuul.ComponentRegistry           INFO     Noticed new executor component np6bc1754cc6fe40000000000
2025-10-28 15:33:08,725 zuul.ComponentRegistry           DEBUG    Registry <zuul.zk.components.ComponentRegistry object at 0x7f6998b31810> got event None for executor np6bc1754cc6fe40000000000
2025-10-28 15:33:08,725 zuul.ComponentRegistry           INFO     Component executor np6bc1754cc6fe40000000000 updated: {'accepting_work': False, 'allow_unzoned': False, 'hostname': 'np6bc1754cc6fe4', 'kind': 'executor', 'model_api': 36, 'process_merge_jobs': False, 'state': 'stopped', 'version': '13.0.2.dev15 18a7e5884', 'zone': None}
2025-10-28 15:33:08,728 zuul.ComponentRegistry           INFO     System minimum data model version 36; this component 36
2025-10-28 15:33:08,728 opentelemetry.trace              WARNING  Overriding of current TracerProvider is not allowed
2025-10-28 15:33:08,729 zuul.ComponentRegistry           DEBUG    Registry <zuul.zk.components.ComponentRegistry object at 0x7f6998b31810> got event CHANGED for executor np6bc1754cc6fe40000000000
2025-10-28 15:33:08,729 zuul.ComponentRegistry           INFO     Component executor np6bc1754cc6fe40000000000 updated: {'accepting_work': False, 'allow_unzoned': False, 'hostname': 'np6bc1754cc6fe4', 'kind': 'executor', 'model_api': 36, 'process_merge_jobs': False, 'state': 'stopped', 'version': '13.0.2.dev15 18a7e5884', 'zone': None}
2025-10-28 15:33:08,730 zuul.ComponentRegistry           DEBUG    Registry <zuul.zk.components.ComponentRegistry object at 0x7f6998b31810> got event CHANGED for executor np6bc1754cc6fe40000000000
2025-10-28 15:33:08,730 zuul.ComponentRegistry           INFO     Component executor np6bc1754cc6fe40000000000 updated: {'accepting_work': False, 'allow_unzoned': True, 'hostname': 'np6bc1754cc6fe4', 'kind': 'executor', 'model_api': 36, 'process_merge_jobs': False, 'state': 'stopped', 'version': '13.0.2.dev15 18a7e5884', 'zone': None}
2025-10-28 15:33:08,730 zuul.ExecutorServer              INFO     Starting executor (hostname: np6bc1754cc6fe4) in unpaused mode
2025-10-28 15:33:08,731 zuul.ComponentRegistry           DEBUG    Registry <zuul.zk.components.ComponentRegistry object at 0x7f6998b31810> got event CHANGED for executor np6bc1754cc6fe40000000000
2025-10-28 15:33:08,731 zuul.ComponentRegistry           INFO     Component executor np6bc1754cc6fe40000000000 updated: {'accepting_work': True, 'allow_unzoned': True, 'hostname': 'np6bc1754cc6fe4', 'kind': 'executor', 'model_api': 36, 'process_merge_jobs': False, 'state': 'stopped', 'version': '13.0.2.dev15 18a7e5884', 'zone': None}
2025-10-28 15:33:08,731 zuul.ComponentRegistry           DEBUG    Registry <zuul.zk.components.ComponentRegistry object at 0x7f6998b31810> got event CHANGED for executor np6bc1754cc6fe40000000000
2025-10-28 15:33:08,731 zuul.ComponentRegistry           INFO     Component executor np6bc1754cc6fe40000000000 updated: {'accepting_work': True, 'allow_unzoned': True, 'hostname': 'np6bc1754cc6fe4', 'kind': 'executor', 'model_api': 36, 'process_merge_jobs': True, 'state': 'stopped', 'version': '13.0.2.dev15 18a7e5884', 'zone': None}
2025-10-28 15:33:08,732 zuul.ExecutorQueue               DEBUG    Creating executor queue at root /zuul/executor/unzoned
2025-10-28 15:33:08,733 zuul.zk.ZooKeeper                DEBUG    Initialize cache at /zuul/executor/unzoned
2025-10-28 15:33:08,736 zuul.zk.ZooKeeper                DEBUG    Cache at /zuul/executor/unzoned is ready
2025-10-28 15:33:08,736 zuul.ExecutorServer              DEBUG    Starting merger
2025-10-28 15:33:08,736 zuul.ExecutorServer              WARNING  Multiprocessing context has already been set
2025-10-28 15:33:08,737 zuul.ExecutorServer              DEBUG    Starting command processor
2025-10-28 15:33:08,737 zuul.ExecutorServer              DEBUG    Starting 4 update workers
2025-10-28 15:33:08,739 zuul.TimerDriver                 DEBUG    Starting apscheduler
2025-10-28 15:33:08,739 apscheduler.scheduler            INFO     Scheduler started
2025-10-28 15:33:08,739 apscheduler.scheduler            DEBUG    Looking for jobs to run
2025-10-28 15:33:08,739 apscheduler.scheduler            DEBUG    No jobs; waiting until a job is added
2025-10-28 15:33:08,739 zuul.ComponentRegistry           DEBUG    Registry <zuul.zk.components.ComponentRegistry object at 0x7f6998b31810> got event CHANGED for executor np6bc1754cc6fe40000000000
2025-10-28 15:33:08,740 zuul.ComponentRegistry           INFO     Component executor np6bc1754cc6fe40000000000 updated: {'accepting_work': True, 'allow_unzoned': True, 'hostname': 'np6bc1754cc6fe4', 'kind': 'executor', 'model_api': 36, 'process_merge_jobs': True, 'state': 'running', 'version': '13.0.2.dev15 18a7e5884', 'zone': None}
2025-10-28 15:33:08,740 Zuul.CapabilitiesRegistry        DEBUG    Capabilities "job_history" updated
2025-10-28 15:33:08,740 zuul.BubblewrapDriver            DEBUG    Initializing bubblewrap with oom_score_adj starting: 0, final: 200
2025-10-28 15:33:08,741 zuul.BubblewrapExecutionContext  DEBUG    Bubblewrap command: setpriv --ambient-caps -all choom -n 200 -- bwrap --dir /tmp --tmpfs /tmp --dir /var --dir /var/tmp --dir /run/user/1000 --ro-bind /usr /usr --ro-bind /lib /lib --ro-bind /bin /bin --ro-bind /sbin /sbin --ro-bind /etc/ld.so.cache /etc/ld.so.cache --ro-bind /etc/resolv.conf /etc/resolv.conf --ro-bind /etc/hosts /etc/hosts --ro-bind /etc/localtime /etc/localtime --ro-bind /dev/null /dev/null --bind /tmp /tmp --tmpfs /tmp/tmp --proc /proc --dev /dev --chdir /tmp --unshare-all --share-net --die-with-parent --uid 1000 --gid 1000 --file 72 /etc/passwd --file 73 /etc/group --ro-bind /lib64 /lib64 --ro-bind /etc/nsswitch.conf /etc/nsswitch.conf --ro-bind /etc/alternatives /etc/alternatives --ro-bind /etc/ssl/certs /etc/ssl/certs --ro-bind /etc/subuid /etc/subuid
2025-10-28 15:33:08,749 opentelemetry.trace              WARNING  Overriding of current TracerProvider is not allowed
2025-10-28 15:33:08,756 zuul.zk.base.ZooKeeperClient     DEBUG    ZooKeeper connection (session: 0x10000076ee72065): CONNECTED
2025-10-28 15:33:08,757 zuul.Component                   INFO     Registering component in ZooKeeper /zuul/components/launcher/launcher-0
2025-10-28 15:33:08,757 zuul.zk.ZooKeeper                DEBUG    Initialize cache at /zuul/nodeset
2025-10-28 15:33:08,757 zuul.ComponentRegistry           INFO     Noticed new launcher component launcher-00000000000
2025-10-28 15:33:08,758 zuul.ComponentRegistry           DEBUG    Registry <zuul.zk.components.ComponentRegistry object at 0x7f6998b31810> got event None for launcher launcher-00000000000
2025-10-28 15:33:08,758 zuul.ComponentRegistry           INFO     Component launcher launcher-00000000000 updated: {'connection_filter': None, 'hostname': 'launcher-0', 'kind': 'launcher', 'model_api': 36, 'state': 'stopped', 'version': '13.0.2.dev15 18a7e5884'}
2025-10-28 15:33:08,759 zuul.zk.ZooKeeper                DEBUG    Cache at /zuul/nodeset is ready
2025-10-28 15:33:08,759 zuul.zk.ZooKeeper                DEBUG    Initialize cache at /zuul/nodes
2025-10-28 15:33:08,761 zuul.zk.ZooKeeper                DEBUG    Cache at /zuul/nodes is ready
2025-10-28 15:33:08,762 zuul.zk.ZooKeeper                DEBUG    Initialize cache at /zuul/images
2025-10-28 15:33:08,764 zuul.zk.ZooKeeper                DEBUG    Cache at /zuul/images is ready
2025-10-28 15:33:08,764 zuul.zk.ZooKeeper                DEBUG    Initialize cache at /zuul/image-uploads
2025-10-28 15:33:08,765 zuul.zk.ZooKeeper                DEBUG    Cache at /zuul/image-uploads is ready
2025-10-28 15:33:08,765 zuul.Launcher                    DEBUG    Cleaning up temp dir
2025-10-28 15:33:08,765 zuul.Launcher                    DEBUG    Starting command processor
2025-10-28 15:33:08,766 zuul.Launcher                    DEBUG    Starting nodescan worker
2025-10-28 15:33:08,766 zuul.Launcher                    DEBUG    Starting launcher thread
2025-10-28 15:33:08,766 zuul.Launcher                    DEBUG    Running stats election
2025-10-28 15:33:08,767 zuul.TimerDriver                 DEBUG    Starting apscheduler
2025-10-28 15:33:08,767 apscheduler.scheduler            INFO     Scheduler started
2025-10-28 15:33:08,767 apscheduler.scheduler            DEBUG    Looking for jobs to run
2025-10-28 15:33:08,767 apscheduler.scheduler            DEBUG    No jobs; waiting until a job is added
2025-10-28 15:33:08,767 Zuul.CapabilitiesRegistry        DEBUG    Capabilities "job_history" updated
2025-10-28 15:33:08,767 zuul.BubblewrapDriver            DEBUG    Initializing bubblewrap with oom_score_adj starting: 0, final: 200
2025-10-28 15:33:08,769 zuul.Launcher                    DEBUG    Launcher running
2025-10-28 15:33:08,769 zuul.ComponentRegistry           DEBUG    Registry <zuul.zk.components.ComponentRegistry object at 0x7f6998b31810> got event CHANGED for launcher launcher-00000000000
2025-10-28 15:33:08,769 zuul.ComponentRegistry           INFO     Component launcher launcher-00000000000 updated: {'connection_filter': None, 'hostname': 'launcher-0', 'kind': 'launcher', 'model_api': 36, 'state': 'running', 'version': '13.0.2.dev15 18a7e5884'}
2025-10-28 15:33:08,772 zuul.BubblewrapExecutionContext  DEBUG    Bubblewrap command: setpriv --ambient-caps -all choom -n 200 -- bwrap --dir /tmp --tmpfs /tmp --dir /var --dir /var/tmp --dir /run/user/1000 --ro-bind /usr /usr --ro-bind /lib /lib --ro-bind /bin /bin --ro-bind /sbin /sbin --ro-bind /etc/ld.so.cache /etc/ld.so.cache --ro-bind /etc/resolv.conf /etc/resolv.conf --ro-bind /etc/hosts /etc/hosts --ro-bind /etc/localtime /etc/localtime --ro-bind /dev/null /dev/null --bind /tmp /tmp --tmpfs /tmp/tmp --proc /proc --dev /dev --chdir /tmp --unshare-all --share-net --die-with-parent --uid 1000 --gid 1000 --file 68 /etc/passwd --file 64 /etc/group --ro-bind /lib64 /lib64 --ro-bind /etc/nsswitch.conf /etc/nsswitch.conf --ro-bind /etc/alternatives /etc/alternatives --ro-bind /etc/ssl/certs /etc/ssl/certs --ro-bind /etc/subuid /etc/subuid
2025-10-28 15:33:08,777 zuul.Launcher                    DEBUG    Won stats election
2025-10-28 15:33:08,783 zuul.SQLConnection               INFO     Initializing SQL connection database (prefix: )
2025-10-28 15:33:08,797 zuul.github.graphql              DEBUG    Loading prepared graphql queries
2025-10-28 15:33:08,798 zuul.test.FakeGithubClientManager INFO     Authing to GitHub
2025-10-28 15:33:08,800 opentelemetry.trace              WARNING  Overriding of current TracerProvider is not allowed
2025-10-28 15:33:08,819 zuul.zk.base.ZooKeeperClient     DEBUG    ZooKeeper connection (session: 0x10000076ee72066): CONNECTED
2025-10-28 15:33:08,820 zuul.Component                   INFO     Registering component in ZooKeeper /zuul/components/scheduler/np6bc1754cc6fe4
2025-10-28 15:33:08,822 zuul.ComponentRegistry           INFO     Noticed new scheduler component np6bc1754cc6fe40000000000
2025-10-28 15:33:08,823 zuul.ComponentRegistry           DEBUG    Registry <zuul.zk.components.ComponentRegistry object at 0x7f6998b31810> got event None for scheduler np6bc1754cc6fe40000000000
2025-10-28 15:33:08,824 zuul.ComponentRegistry           INFO     Component scheduler np6bc1754cc6fe40000000000 updated: {'hostname': 'np6bc1754cc6fe4', 'kind': 'scheduler', 'model_api': 36, 'state': 'stopped', 'version': '13.0.2.dev15 18a7e5884'}
2025-10-28 15:33:08,829 zuul.zk.ZooKeeper                DEBUG    Initialize cache at /keystorage-oidc
2025-10-28 15:33:08,831 zuul.zk.ZooKeeper                DEBUG    Cache at /keystorage-oidc is ready
2025-10-28 15:33:08,833 zuul.ExecutorQueue               DEBUG    Creating executor queue at root /zuul/executor/unzoned
2025-10-28 15:33:08,837 zuul.zk.ZooKeeper                DEBUG    Initialize cache at /zuul/executor/unzoned
2025-10-28 15:33:08,846 zuul.zk.ZooKeeper                DEBUG    Cache at /zuul/executor/unzoned is ready
2025-10-28 15:33:08,849 zuul.zk.ZooKeeper                DEBUG    Initialize cache at /zuul/merger
2025-10-28 15:33:08,870 zuul.zk.ZooKeeper                DEBUG    Cache at /zuul/merger is ready
2025-10-28 15:33:08,878 zuul.nodepool                    DEBUG    Running nodepool watcher election
2025-10-28 15:33:08,879 zuul.TimerDriver                 DEBUG    Starting timer election loop
2025-10-28 15:33:08,879 zuul.TimerDriver                 INFO     Running timer election
2025-10-28 15:33:08,895 zuul.nodepool                    INFO     Watching nodepool requests
2025-10-28 15:33:08,895 zuul.TimerDriver                 INFO     Won timer election
2025-10-28 15:33:08,902 alembic.runtime.migration        INFO     Context impl MariaDBImpl.
2025-10-28 15:33:08,902 alembic.runtime.migration        INFO     Will assume non-transactional DDL.
2025-10-28 15:33:08,903 zuul.SQLConnection               DEBUG    Current migration revision: None
2025-10-28 15:33:08,984 alembic.runtime.migration        INFO     Context impl MariaDBImpl.
2025-10-28 15:33:08,984 alembic.runtime.migration        INFO     Will assume non-transactional DDL.
2025-10-28 15:33:08,990 alembic.runtime.migration        INFO     Running stamp_revision  -> 6c1582c1d08c
2025-10-28 15:33:08,991 alembic.runtime.migration        DEBUG    new branch insert 6c1582c1d08c
2025-10-28 15:33:08,993 zuul.test.FakeGerritConnection   DEBUG    Starting Gerrit Connection/Watchers
2025-10-28 15:33:08,993 zuul.test.FakeGerritConnection   DEBUG    GET: http://localhost:52721/a/config/server/version
2025-10-28 15:33:08,994 responses                        INFO     request.allowed-passthru
2025-10-28 15:33:08,994 urllib3.connectionpool           DEBUG    Starting new HTTP connection (1): localhost:52721
2025-10-28 15:33:08,995 zuul.test.FakeGerritConnection   DEBUG    Got GET /a/config/server/version
2025-10-28 15:33:08,995 zuul.test.FakeGerritConnection   DEBUG    "GET /a/config/server/version HTTP/1.1" 200 -
2025-10-28 15:33:08,997 urllib3.connectionpool           DEBUG    http://localhost:52721 "GET /a/config/server/version HTTP/1.1" 200 23
2025-10-28 15:33:08,997 zuul.GerritConnection.io         DEBUG    Received: 200 )]}'
"3.0.0-some-stuff"
2025-10-28 15:33:08,997 zuul.test.FakeGerritConnection   INFO     Remote version is: 3.0.0-some-stuff (parsed as (3, 0, 0))
2025-10-28 15:33:08,997 zuul.test.FakeGerritConnection   DEBUG    GET: http://localhost:52721/a/config/server/info
2025-10-28 15:33:08,997 responses                        INFO     request.allowed-passthru
2025-10-28 15:33:08,997 urllib3.connectionpool           DEBUG    Resetting dropped connection: localhost
2025-10-28 15:33:08,999 zuul.test.FakeGerritConnection   DEBUG    Got GET /a/config/server/info
2025-10-28 15:33:08,999 zuul.test.FakeGerritConnection   DEBUG    "GET /a/config/server/info HTTP/1.1" 200 -
2025-10-28 15:33:08,999 urllib3.connectionpool           DEBUG    http://localhost:52721 "GET /a/config/server/info HTTP/1.1" 200 603
2025-10-28 15:33:08,999 zuul.GerritConnection.io         DEBUG    Received: 200 )]}'
{"accounts": {"visibility": "ALL", "default_display_name": "FULL_NAME"}, "change": {"allow_blame": true, "disable_private_changes": true, "update_delay": 300, "mergeability_computation_behavior": "API_REF_UPDATED_AND_CHANGE_REINDEX", "enable_robot_comments": true, "conflicts_predicate_enabled": true}, "gerrit": {"all_projects": "All-Projects", "all_users": "All-Users", "doc_search": true}, "note_db_enabled": true, "sshd": {}, "suggest": {"from": 0}, "user": {"anonymous_coward_name": "Name of user not set"}, "receive": {"enable_signed_push": false}, "submit_requirement_dashboard_columns": []}
2025-10-28 15:33:08,999 zuul.test.FakeGerritConnection   INFO     Remote submitWholeTopic: False
2025-10-28 15:33:08,999 zuul.test.FakeGerritConnection   DEBUG    Creating Zookeeper branch cache
2025-10-28 15:33:09,024 zuul.BranchCache.gerrit          ERROR    Exception loading ZKObject at /zuul/cache/connection/gerrit/branches/data
2025-10-28 15:33:09,037 zuul.test.FakeGerritConnection   INFO     Creating Zookeeper event queue
2025-10-28 15:33:09,054 zuul.test.FakeGerritConnection   DEBUG    Creating Zookeeper change cache
2025-10-28 15:33:09,059 zuul.test.FakeGithubConnection   INFO     Starting GitHub connection: github
2025-10-28 15:33:09,059 zuul.test.FakeGithubClientManager INFO     Authing to GitHub
2025-10-28 15:33:09,059 zuul.test.FakeGithubConnection   DEBUG    Creating Zookeeper branch cache
2025-10-28 15:33:09,062 zuul.BranchCache.github          ERROR    Exception loading ZKObject at /zuul/cache/connection/github/branches/data
2025-10-28 15:33:09,065 zuul.test.FakeGithubConnection   DEBUG    Creating Zookeeper event queue
2025-10-28 15:33:09,075 zuul.test.FakeGithubConnection   DEBUG    Creating Zookeeper change cache
2025-10-28 15:33:09,086 zuul.test.FakeGithubConnection   INFO     Starting event connector
2025-10-28 15:33:09,086 zuul.Scheduler-0                 DEBUG    Statsd enabled
2025-10-28 15:33:09,086 zuul.Scheduler-0                 DEBUG    Run handler sleeping
2025-10-28 15:33:09,086 zuul.Scheduler-0                 DEBUG    Run handler awake
2025-10-28 15:33:09,086 zuul.Scheduler-0                 DEBUG    Starting command processor
2025-10-28 15:33:09,087 zuul.Scheduler-0                 DEBUG    Running stats election
2025-10-28 15:33:09,087 apscheduler.scheduler            INFO     Scheduler started
2025-10-28 15:33:09,087 apscheduler.scheduler            DEBUG    Looking for jobs to run
2025-10-28 15:33:09,087 apscheduler.scheduler            DEBUG    No jobs; waiting until a job is added
2025-10-28 15:33:09,089 zuul.Scheduler-0                 INFO     Priming scheduler config
2025-10-28 15:33:09,089 zuul.ComponentRegistry           DEBUG    Registry <zuul.zk.components.ComponentRegistry object at 0x7f6998b31810> got event CHANGED for scheduler np6bc1754cc6fe40000000000
2025-10-28 15:33:09,089 zuul.ComponentRegistry           INFO     Component scheduler np6bc1754cc6fe40000000000 updated: {'hostname': 'np6bc1754cc6fe4', 'kind': 'scheduler', 'model_api': 36, 'state': 'initializing', 'version': '13.0.2.dev15 18a7e5884'}
2025-10-28 15:33:09,089 zuul.RendezvousElection          DEBUG    Election winner for /zuul/events/connection/github/election is None
2025-10-28 15:33:09,089 zuul.RendezvousElection          DEBUG    Election winner for /zuul/events/connection/gerrit/election is None
2025-10-28 15:33:09,094 zuul.Scheduler-0                 DEBUG    Won stats election
2025-10-28 15:33:09,096 zuul.Scheduler-0                 INFO     Creating initial system config
2025-10-28 15:33:09,096 zuul.ConfigLoader                INFO     Loading configuration from /tmp/zuul-test/tmpqh2ozn2c/zuul-test/config/tmp78f6l06z
2025-10-28 15:33:09,097 zuul.Scheduler-0                 DEBUG    Run handler sleeping
2025-10-28 15:33:09,101 zuul.Scheduler-0                 DEBUG    Run handler awake
2025-10-28 15:33:09,186 zuul.Scheduler-0                 DEBUG    Wait for tenant-one write tenant lock (id: None)
2025-10-28 15:33:09,193 zuul.Scheduler-0                 DEBUG    Aquired tenant-one write tenant lock (id: None)
2025-10-28 15:33:09,201 git.util                         DEBUG    sys.platform='linux', git_executable='git'
2025-10-28 15:33:09,202 git.util                         DEBUG    sys.platform='linux', git_executable='git'
2025-10-28 15:33:09,240 zuul.Scheduler-0                 DEBUG    Run handler sleeping
2025-10-28 15:33:09,242 zuul.test.FakeGerritConnection   DEBUG    Fetched 1 branches for org/project
2025-10-28 15:33:09,242 zuul.test.FakeGerritConnection   INFO     Got branches for org/project
2025-10-28 15:33:09,244 zuul.test.FakeGerritConnection   DEBUG    Fetched 1 branches for org/common-config
2025-10-28 15:33:09,245 zuul.test.FakeGerritConnection   INFO     Got branches for org/common-config
2025-10-28 15:33:09,248 zuul.test.FakeGerritConnection   DEBUG    GET: http://localhost:52721/a/projects/org%2Fproject/HEAD
2025-10-28 15:33:09,248 responses                        INFO     request.allowed-passthru
2025-10-28 15:33:09,249 urllib3.connectionpool           DEBUG    Resetting dropped connection: localhost
2025-10-28 15:33:09,249 zuul.test.FakeGerritConnection   DEBUG    Got GET /a/projects/org%2Fproject/HEAD
2025-10-28 15:33:09,250 zuul.test.FakeGerritConnection   DEBUG    "GET /a/projects/org%2Fproject/HEAD HTTP/1.1" 200 -
2025-10-28 15:33:09,253 urllib3.connectionpool           DEBUG    http://localhost:52721 "GET /a/projects/org%2Fproject/HEAD HTTP/1.1" 200 24
2025-10-28 15:33:09,253 zuul.GerritConnection.io         DEBUG    Received: 200 )]}'
"refs/heads/master"
2025-10-28 15:33:09,253 zuul.test.FakeGerritConnection   INFO     Got default branch for org/project: master
2025-10-28 15:33:09,355 zuul.test.FakeGerritConnection   DEBUG    GET: http://localhost:52721/a/projects/org%2Fcommon-config/HEAD
2025-10-28 15:33:09,355 responses                        INFO     request.allowed-passthru
2025-10-28 15:33:09,355 urllib3.connectionpool           DEBUG    Resetting dropped connection: localhost
2025-10-28 15:33:09,356 zuul.test.FakeGerritConnection   DEBUG    Got GET /a/projects/org%2Fcommon-config/HEAD
2025-10-28 15:33:09,356 zuul.test.FakeGerritConnection   DEBUG    "GET /a/projects/org%2Fcommon-config/HEAD HTTP/1.1" 200 -
2025-10-28 15:33:09,356 urllib3.connectionpool           DEBUG    http://localhost:52721 "GET /a/projects/org%2Fcommon-config/HEAD HTTP/1.1" 200 24
2025-10-28 15:33:09,357 zuul.GerritConnection.io         DEBUG    Received: 200 )]}'
"refs/heads/master"
2025-10-28 15:33:09,357 zuul.test.FakeGerritConnection   INFO     Got default branch for org/common-config: master
2025-10-28 15:33:09,375 zuul.MergeClient                 DEBUG    Submitting job b5d53bb6c599416c916fb7518858232c with data {'connection': 'gerrit', 'project': 'org/common-config', 'branch': 'master', 'files': ['zuul.yaml', '.zuul.yaml'], 'dirs': ['zuul.d', '.zuul.d']}
2025-10-28 15:33:09,376 zuul.MergerApi                   DEBUG    Appending merge job to history: b5d53bb6c599416c916fb7518858232c
2025-10-28 15:33:09,376 zuul.MergeClient                 DEBUG    Submitting job fae8c993fb154385bbb067bc3b6b9d68 with data {'connection': 'gerrit', 'project': 'org/project', 'branch': 'master', 'files': ['zuul.yaml', '.zuul.yaml'], 'dirs': ['zuul.d', '.zuul.d']}
2025-10-28 15:33:09,376 zuul.MergerApi                   DEBUG    Appending merge job to history: fae8c993fb154385bbb067bc3b6b9d68
2025-10-28 15:33:09,381 zuul.MergerApi                   DEBUG    Submitting job request to ZooKeeper <MergeRequest b5d53bb6c599416c916fb7518858232c, job_type=cat, state=requested, path=/zuul/merger/requests/b5d53bb6c599416c916fb7518858232c>
2025-10-28 15:33:09,382 zuul.MergerApi                   DEBUG    Submitting job request to ZooKeeper <MergeRequest fae8c993fb154385bbb067bc3b6b9d68, job_type=cat, state=requested, path=/zuul/merger/requests/fae8c993fb154385bbb067bc3b6b9d68>
2025-10-28 15:33:09,396 zuul.TenantParser                DEBUG    Submitting cat job <JobResultFuture request_path=/zuul/merger/requests/b5d53bb6c599416c916fb7518858232c> for gerrit org/common-config master
2025-10-28 15:33:09,399 zuul.TenantParser                DEBUG    Submitting cat job <JobResultFuture request_path=/zuul/merger/requests/fae8c993fb154385bbb067bc3b6b9d68> for gerrit org/project master
2025-10-28 15:33:09,399 zuul.TenantParser                DEBUG    Waiting for cat job <JobResultFuture request_path=/zuul/merger/requests/b5d53bb6c599416c916fb7518858232c>
2025-10-28 15:33:09,418 zuul.JobRequestQueue             DEBUG    [build: b5d53bb6c599416c916fb7518858232c] Updating request <MergeRequest b5d53bb6c599416c916fb7518858232c, job_type=cat, state=running, path=/zuul/merger/requests/b5d53bb6c599416c916fb7518858232c>
2025-10-28 15:33:09,422 zuul.ExecutorServer              DEBUG    Next executed merge job: <MergeRequest b5d53bb6c599416c916fb7518858232c, job_type=cat, state=running, path=/zuul/merger/requests/b5d53bb6c599416c916fb7518858232c>
2025-10-28 15:33:09,422 zuul.ExecutorServer              DEBUG    Got cat job: b5d53bb6c599416c916fb7518858232c
2025-10-28 15:33:09,422 zuul.ExecutorServer              INFO     Updating repo gerrit/org/common-config
2025-10-28 15:33:09,422 zuul.Repo                        DEBUG    Cloning from file:///tmp/zuul-test/tmpqh2ozn2c/zuul-test/upstream/org/common-config to /tmp/zuul-test/tmpqh2ozn2c/zuul-test/executor-git/review.example.com/org/org%2Fcommon-config
2025-10-28 15:33:09,422 git.util                         DEBUG    sys.platform='linux', git_executable='git'
2025-10-28 15:33:09,435 git.util                         DEBUG    sys.platform='linux', git_executable='git'
2025-10-28 15:33:09,445 git.util                         DEBUG    sys.platform='linux', git_executable='git'
2025-10-28 15:33:09,446 zuul.Merger                      INFO     Updating local repository gerrit/org/common-config
2025-10-28 15:33:09,446 git.util                         DEBUG    sys.platform='linux', git_executable='git'
2025-10-28 15:33:09,446 git.util                         DEBUG    sys.platform='linux', git_executable='git'
2025-10-28 15:33:09,447 zuul.Repo                        DEBUG    Updating repository /tmp/zuul-test/tmpqh2ozn2c/zuul-test/executor-git/review.example.com/org/org%2Fcommon-config
2025-10-28 15:33:09,449 git.util                         DEBUG    sys.platform='linux', git_executable='git'
2025-10-28 15:33:09,449 git.util                         DEBUG    sys.platform='linux', git_executable='git'
2025-10-28 15:33:09,466 zuul.ExecutorServer              DEBUG    Finished updating repo gerrit/org/common-config
2025-10-28 15:33:09,467 zuul.Repo                        DEBUG    Resetting repository /tmp/zuul-test/tmpqh2ozn2c/zuul-test/executor-git/review.example.com/org/org%2Fcommon-config
2025-10-28 15:33:09,467 git.util                         DEBUG    sys.platform='linux', git_executable='git'
2025-10-28 15:33:09,467 git.util                         DEBUG    sys.platform='linux', git_executable='git'
2025-10-28 15:33:09,469 git.util                         DEBUG    sys.platform='linux', git_executable='git'
2025-10-28 15:33:09,475 git.util                         DEBUG    sys.platform='linux', git_executable='git'
2025-10-28 15:33:09,475 git.util                         DEBUG    sys.platform='linux', git_executable='git'
2025-10-28 15:33:09,489 zuul.Repo                        DEBUG    Getting files for /tmp/zuul-test/tmpqh2ozn2c/zuul-test/executor-git/review.example.com/org/org%2Fcommon-config at 50941099f5696e1fd9bf788581e4a83518f3513a
2025-10-28 15:33:09,494 zuul.ExecutorServer              DEBUG    Completed cat job b5d53bb6c599416c916fb7518858232c: payload size: 2370
2025-10-28 15:33:09,494 zuul.ExecutorServer              INFO     Merge <MergeRequest b5d53bb6c599416c916fb7518858232c, job_type=cat, state=running, path=/zuul/merger/requests/b5d53bb6c599416c916fb7518858232c> complete, merged: False, updated: True, commit: None, branches: []
2025-10-28 15:33:09,494 zuul.ExecutorServer              DEBUG    Providing synchronous result via future for <MergeRequest b5d53bb6c599416c916fb7518858232c, job_type=cat, state=running, path=/zuul/merger/requests/b5d53bb6c599416c916fb7518858232c>
2025-10-28 15:33:09,503 zuul.JobRequestQueue             DEBUG    [build: b5d53bb6c599416c916fb7518858232c] Updating request <MergeRequest b5d53bb6c599416c916fb7518858232c, job_type=cat, state=completed, path=/zuul/merger/requests/b5d53bb6c599416c916fb7518858232c>
2025-10-28 15:33:09,507 zuul.test.TestingMergerApi       DEBUG    Removing request <MergeRequest b5d53bb6c599416c916fb7518858232c, job_type=cat, state=completed, path=/zuul/merger/requests/b5d53bb6c599416c916fb7518858232c>
2025-10-28 15:33:09,515 zuul.TenantParser                DEBUG    Cat job <JobResultFuture request_path=/zuul/merger/requests/b5d53bb6c599416c916fb7518858232c> got files dict_keys(['.zuul.yaml', 'zuul.yaml'])
2025-10-28 15:33:09,515 zuul.TenantParser                INFO     Loading configuration from org/common-config/zuul.yaml@master
2025-10-28 15:33:09,534 zuul.JobRequestQueue             DEBUG    [build: fae8c993fb154385bbb067bc3b6b9d68] Updating request <MergeRequest fae8c993fb154385bbb067bc3b6b9d68, job_type=cat, state=running, path=/zuul/merger/requests/fae8c993fb154385bbb067bc3b6b9d68>
2025-10-28 15:33:09,537 zuul.ExecutorServer              DEBUG    Next executed merge job: <MergeRequest fae8c993fb154385bbb067bc3b6b9d68, job_type=cat, state=running, path=/zuul/merger/requests/fae8c993fb154385bbb067bc3b6b9d68>
2025-10-28 15:33:09,537 zuul.ExecutorServer              DEBUG    Got cat job: fae8c993fb154385bbb067bc3b6b9d68
2025-10-28 15:33:09,537 zuul.ExecutorServer              INFO     Updating repo gerrit/org/project
2025-10-28 15:33:09,538 zuul.Repo                        DEBUG    Cloning from file:///tmp/zuul-test/tmpqh2ozn2c/zuul-test/upstream/org/project to /tmp/zuul-test/tmpqh2ozn2c/zuul-test/executor-git/review.example.com/org/org%2Fproject
2025-10-28 15:33:09,538 git.util                         DEBUG    sys.platform='linux', git_executable='git'
2025-10-28 15:33:09,547 zuul.TenantParser                DEBUG    Waiting for cat job <JobResultFuture request_path=/zuul/merger/requests/fae8c993fb154385bbb067bc3b6b9d68>
2025-10-28 15:33:09,553 git.util                         DEBUG    sys.platform='linux', git_executable='git'
2025-10-28 15:33:09,560 git.util                         DEBUG    sys.platform='linux', git_executable='git'
2025-10-28 15:33:09,561 zuul.Merger                      INFO     Updating local repository gerrit/org/project
2025-10-28 15:33:09,561 git.util                         DEBUG    sys.platform='linux', git_executable='git'
2025-10-28 15:33:09,562 git.util                         DEBUG    sys.platform='linux', git_executable='git'
2025-10-28 15:33:09,563 zuul.Repo                        DEBUG    Updating repository /tmp/zuul-test/tmpqh2ozn2c/zuul-test/executor-git/review.example.com/org/org%2Fproject
2025-10-28 15:33:09,574 git.util                         DEBUG    sys.platform='linux', git_executable='git'
2025-10-28 15:33:09,574 git.util                         DEBUG    sys.platform='linux', git_executable='git'
2025-10-28 15:33:09,593 zuul.ExecutorServer              DEBUG    Finished updating repo gerrit/org/project
2025-10-28 15:33:09,593 zuul.Repo                        DEBUG    Resetting repository /tmp/zuul-test/tmpqh2ozn2c/zuul-test/executor-git/review.example.com/org/org%2Fproject
2025-10-28 15:33:09,593 git.util                         DEBUG    sys.platform='linux', git_executable='git'
2025-10-28 15:33:09,594 git.util                         DEBUG    sys.platform='linux', git_executable='git'
2025-10-28 15:33:09,595 git.util                         DEBUG    sys.platform='linux', git_executable='git'
2025-10-28 15:33:09,610 git.util                         DEBUG    sys.platform='linux', git_executable='git'
2025-10-28 15:33:09,611 git.util                         DEBUG    sys.platform='linux', git_executable='git'
2025-10-28 15:33:09,615 zuul.Repo                        DEBUG    Getting files for /tmp/zuul-test/tmpqh2ozn2c/zuul-test/executor-git/review.example.com/org/org%2Fproject at cf12fee35f5ece77bb533eeab80924a3e558b77c
2025-10-28 15:33:09,617 zuul.ExecutorServer              DEBUG    Completed cat job fae8c993fb154385bbb067bc3b6b9d68: payload size: 153
2025-10-28 15:33:09,617 zuul.ExecutorServer              INFO     Merge <MergeRequest fae8c993fb154385bbb067bc3b6b9d68, job_type=cat, state=running, path=/zuul/merger/requests/fae8c993fb154385bbb067bc3b6b9d68> complete, merged: False, updated: True, commit: None, branches: []
2025-10-28 15:33:09,617 zuul.ExecutorServer              DEBUG    Providing synchronous result via future for <MergeRequest fae8c993fb154385bbb067bc3b6b9d68, job_type=cat, state=running, path=/zuul/merger/requests/fae8c993fb154385bbb067bc3b6b9d68>
2025-10-28 15:33:09,627 zuul.JobRequestQueue             DEBUG    [build: fae8c993fb154385bbb067bc3b6b9d68] Updating request <MergeRequest fae8c993fb154385bbb067bc3b6b9d68, job_type=cat, state=completed, path=/zuul/merger/requests/fae8c993fb154385bbb067bc3b6b9d68>
2025-10-28 15:33:09,630 zuul.test.TestingMergerApi       DEBUG    Removing request <MergeRequest fae8c993fb154385bbb067bc3b6b9d68, job_type=cat, state=completed, path=/zuul/merger/requests/fae8c993fb154385bbb067bc3b6b9d68>
2025-10-28 15:33:09,634 zuul.TenantParser                DEBUG    Cat job <JobResultFuture request_path=/zuul/merger/requests/fae8c993fb154385bbb067bc3b6b9d68> got files dict_keys(['.zuul.yaml', 'zuul.yaml'])
2025-10-28 15:33:09,638 zuul.TenantParser                DEBUG    Created layout id 52568859162e4f54bab8d9fe3dc095d1
2025-10-28 15:33:09,640 zuul.Pipeline.tenant-one.check   DEBUG    Building relative_priority queues
2025-10-28 15:33:09,643 zuul.Pipeline.tenant-one.check   ERROR    Exception loading ZKObject at /zuul/tenant/tenant-one/pipeline/check
2025-10-28 15:33:09,643 zuul.Pipeline.tenant-one.check   WARNING  Initializing pipeline state for check; this is expected only for new pipelines
2025-10-28 15:33:09,658 zuul.Pipeline.tenant-one.check   ERROR    Exception loading ZKObject at /zuul/tenant/tenant-one/pipeline/check/change_list
2025-10-28 15:33:09,658 zuul.Pipeline.tenant-one.check   WARNING  Initializing pipeline change list for check; this is expected only for new pipelines
2025-10-28 15:33:09,664 zuul.Pipeline.tenant-one.gate    DEBUG    Building shared change queues
2025-10-28 15:33:09,664 zuul.Pipeline.tenant-one.gate    DEBUG    Created queue: <zuul.manager.shared.ChangeQueueManager object at 0x7f68e0c3e510>
2025-10-28 15:33:09,664 zuul.Pipeline.tenant-one.gate    DEBUG    Added project org/project to queue managers: <zuul.manager.shared.ChangeQueueManager object at 0x7f68e0c3e510>
2025-10-28 15:33:09,668 zuul.Pipeline.tenant-one.gate    ERROR    Exception loading ZKObject at /zuul/tenant/tenant-one/pipeline/gate
2025-10-28 15:33:09,668 zuul.Pipeline.tenant-one.gate    WARNING  Initializing pipeline state for gate; this is expected only for new pipelines
2025-10-28 15:33:09,670 zuul.Pipeline.tenant-one.gate    ERROR    Exception loading ZKObject at /zuul/tenant/tenant-one/pipeline/gate/change_list
2025-10-28 15:33:09,670 zuul.Pipeline.tenant-one.gate    WARNING  Initializing pipeline change list for gate; this is expected only for new pipelines
2025-10-28 15:33:09,687 zuul.Pipeline.tenant-one.post    DEBUG    Building relative_priority queues
2025-10-28 15:33:09,689 zuul.Pipeline.tenant-one.post    ERROR    Exception loading ZKObject at /zuul/tenant/tenant-one/pipeline/post
2025-10-28 15:33:09,689 zuul.Pipeline.tenant-one.post    WARNING  Initializing pipeline state for post; this is expected only for new pipelines
2025-10-28 15:33:09,690 zuul.Pipeline.tenant-one.post    ERROR    Exception loading ZKObject at /zuul/tenant/tenant-one/pipeline/post/change_list
2025-10-28 15:33:09,690 zuul.Pipeline.tenant-one.post    WARNING  Initializing pipeline change list for post; this is expected only for new pipelines
2025-10-28 15:33:09,695 zuul.Pipeline.tenant-one.tag     DEBUG    Building relative_priority queues
2025-10-28 15:33:09,696 zuul.Pipeline.tenant-one.tag     ERROR    Exception loading ZKObject at /zuul/tenant/tenant-one/pipeline/tag
2025-10-28 15:33:09,696 zuul.Pipeline.tenant-one.tag     WARNING  Initializing pipeline state for tag; this is expected only for new pipelines
2025-10-28 15:33:09,697 zuul.Pipeline.tenant-one.tag     ERROR    Exception loading ZKObject at /zuul/tenant/tenant-one/pipeline/tag/change_list
2025-10-28 15:33:09,697 zuul.Pipeline.tenant-one.tag     WARNING  Initializing pipeline change list for tag; this is expected only for new pipelines
2025-10-28 15:33:09,707 zuul.ConfigLoader                WARNING  1 errors detected during tenant-one tenant configuration loading
2025-10-28 15:33:09,707 zuul.ConfigLoader                WARNING  Zuul encountered a deprecated syntax while parsing its
configuration in the repo org/common-config on branch master.  The
problem was:

  All regular expressions must conform to RE2 syntax, but an
  expression using the deprecated Perl-style syntax has been detected.
  Adjust the configuration to conform to RE2 syntax.
  
  The RE2 syntax error is: invalid perl operator: (?!

The problem appears in the "ref" attribute
of the "post" pipeline stanza:

  ...
      name: post
      manager: independent
      trigger:
        gerrit:
          - event: ref-updated
            ref: ^(?!refs/).*$

  in "org/common-config/zuul.yaml@master", line 40
2025-10-28 15:33:09,723 zuul.test.FakeGerritConnection   DEBUG    Setting watched checkers to []
2025-10-28 15:33:09,723 zuul.test.FakeGerritConnection   DEBUG    Setting watched event filters for tenant-one to [<GerritEventFilter connection: gerrit types: patchset-created ignore_deletes: True>, <GerritEventFilter connection: gerrit types: comment-added ignore_deletes: True event_approvals: Approved:1>, <GerritEventFilter connection: gerrit types: ref-updated refs: ^(?!refs/).*$ ignore_deletes: True>, <GerritEventFilter connection: gerrit types: ref-updated refs: ^refs/tags/.*$ ignore_deletes: True>]
2025-10-28 15:33:09,723 zuul.test.FakeGerritConnection   DEBUG    Setting watched event filters to {<GerritEventFilter connection: gerrit types: ref-updated refs: ^refs/tags/.*$ ignore_deletes: True>, <GerritEventFilter connection: gerrit types: patchset-created ignore_deletes: True>, <GerritEventFilter connection: gerrit types: ref-updated refs: ^(?!refs/).*$ ignore_deletes: True>, <GerritEventFilter connection: gerrit types: comment-added ignore_deletes: True event_approvals: Approved:1>}
2025-10-28 15:33:09,762 zuul.Scheduler-0                 DEBUG    Run handler awake
2025-10-28 15:33:09,809 zuul.Scheduler-0                 DEBUG    Skipping management event queue for tenant tenant-one
2025-10-28 15:33:09,823 zuul.Scheduler-0                 DEBUG    Skipping locked tenant tenant-one
2025-10-28 15:33:09,825 zuul.Scheduler-0                 DEBUG    Run handler sleeping
2025-10-28 15:33:09,825 zuul.Scheduler-0                 DEBUG    Run handler awake
2025-10-28 15:33:09,832 zuul.Scheduler-0                 DEBUG    Skipping management event queue for tenant tenant-one
2025-10-28 15:33:09,836 zuul.Scheduler-0                 DEBUG    Skipping locked tenant tenant-one
2025-10-28 15:33:09,837 zuul.Scheduler-0                 DEBUG    Run handler sleeping
2025-10-28 15:33:09,837 zuul.Scheduler-0                 DEBUG    Run handler awake
2025-10-28 15:33:09,851 zuul.Scheduler-0                 DEBUG    Skipping management event queue for tenant tenant-one
2025-10-28 15:33:09,856 zuul.Scheduler-0                 DEBUG    Skipping locked tenant tenant-one
2025-10-28 15:33:09,858 zuul.Scheduler-0                 DEBUG    Run handler sleeping
2025-10-28 15:33:09,858 zuul.Scheduler-0                 DEBUG    Run handler awake
2025-10-28 15:33:09,874 zuul.Scheduler-0                 DEBUG    Skipping management event queue for tenant tenant-one
2025-10-28 15:33:09,882 zuul.Scheduler-0                 DEBUG    Skipping locked tenant tenant-one
2025-10-28 15:33:09,892 zuul.Scheduler-0                 DEBUG    Run handler sleeping
2025-10-28 15:33:09,892 zuul.Scheduler-0                 DEBUG    Run handler awake
2025-10-28 15:33:09,897 zuul.Scheduler-0                 DEBUG    Skipping management event queue for tenant tenant-one
2025-10-28 15:33:09,899 zuul.Scheduler-0                 DEBUG    Skipping locked tenant tenant-one
2025-10-28 15:33:09,901 zuul.Scheduler-0                 DEBUG    Run handler sleeping
2025-10-28 15:33:09,901 zuul.Scheduler-0                 DEBUG    Run handler awake
2025-10-28 15:33:09,904 zuul.Scheduler-0                 DEBUG    Setting layout state last reconfigure ltime to current ltime 1797446
2025-10-28 15:33:09,905 zuul.Scheduler-0                 DEBUG    Skipping management event queue for tenant tenant-one
2025-10-28 15:33:09,906 zuul.Scheduler-0                 DEBUG    Skipping locked tenant tenant-one
2025-10-28 15:33:09,907 zuul.Scheduler-0                 DEBUG    Run handler sleeping
2025-10-28 15:33:09,907 zuul.Scheduler-0                 DEBUG    Run handler awake
2025-10-28 15:33:09,913 zuul.Scheduler-0                 DEBUG    Skipping management event queue for tenant tenant-one
2025-10-28 15:33:09,915 zuul.Scheduler-0                 DEBUG    Skipping locked tenant tenant-one
2025-10-28 15:33:09,916 zuul.Scheduler-0                 DEBUG    Run handler sleeping
2025-10-28 15:33:09,916 zuul.Scheduler-0                 DEBUG    Run handler awake
2025-10-28 15:33:09,917 zuul.test.FakeGerritConnection   DEBUG    Setting watched checkers to []
2025-10-28 15:33:09,917 zuul.test.FakeGerritConnection   DEBUG    Setting watched event filters for tenant-one to [<GerritEventFilter connection: gerrit types: patchset-created ignore_deletes: True>, <GerritEventFilter connection: gerrit types: comment-added ignore_deletes: True event_approvals: Approved:1>, <GerritEventFilter connection: gerrit types: ref-updated refs: ^(?!refs/).*$ ignore_deletes: True>, <GerritEventFilter connection: gerrit types: ref-updated refs: ^refs/tags/.*$ ignore_deletes: True>]
2025-10-28 15:33:09,917 zuul.test.FakeGerritConnection   DEBUG    Setting watched event filters to {<GerritEventFilter connection: gerrit types: ref-updated refs: ^refs/tags/.*$ ignore_deletes: True>, <GerritEventFilter connection: gerrit types: patchset-created ignore_deletes: True>, <GerritEventFilter connection: gerrit types: ref-updated refs: ^(?!refs/).*$ ignore_deletes: True>, <GerritEventFilter connection: gerrit types: comment-added ignore_deletes: True event_approvals: Approved:1>}
2025-10-28 15:33:09,917 zuul.Scheduler-0                 DEBUG    Released tenant-one write tenant lock (id: None)
2025-10-28 15:33:09,919 zuul.Scheduler-0                 INFO     Config priming complete (duration: 0.83 seconds)
2025-10-28 15:33:09,923 zuul.RendezvousElection          DEBUG    Election winner for /zuul/events/connection/github/election is None
2025-10-28 15:33:09,923 zuul.RendezvousElection          DEBUG    Did not win election for /zuul/events/connection/github/election
2025-10-28 15:33:09,923 zuul.RendezvousElection          DEBUG    Did not win election for /zuul/events/connection/github/election
2025-10-28 15:33:09,924 zuul.RendezvousElection          DEBUG    Election winner for /zuul/events/connection/gerrit/election is None
2025-10-28 15:33:09,924 zuul.RendezvousElection          DEBUG    Did not win election for /zuul/events/connection/gerrit/election
2025-10-28 15:33:09,924 zuul.RendezvousElection          DEBUG    Did not win election for /zuul/events/connection/gerrit/election
2025-10-28 15:33:09,925 zuul.ComponentRegistry           DEBUG    Registry <zuul.zk.components.ComponentRegistry object at 0x7f6998b31810> got event CHANGED for scheduler np6bc1754cc6fe40000000000
2025-10-28 15:33:09,925 zuul.ComponentRegistry           INFO     Component scheduler np6bc1754cc6fe40000000000 updated: {'hostname': 'np6bc1754cc6fe4', 'kind': 'scheduler', 'model_api': 36, 'state': 'running', 'version': '13.0.2.dev15 18a7e5884'}
2025-10-28 15:33:09,925 zuul.RendezvousElection          DEBUG    Election winner for /zuul/events/connection/github/election is <SchedulerComponent {'hostname': 'np6bc1754cc6fe4', 'state': 'running', 'kind': 'scheduler', 'version': '13.0.2.dev15 18a7e5884', 'model_api': 36}>
2025-10-28 15:33:09,925 zuul.RendezvousElection          DEBUG    Election winner for /zuul/events/connection/gerrit/election is <SchedulerComponent {'hostname': 'np6bc1754cc6fe4', 'state': 'running', 'kind': 'scheduler', 'version': '13.0.2.dev15 18a7e5884', 'model_api': 36}>
2025-10-28 15:33:09,925 zuul.RendezvousElection          DEBUG    Acquiring lock for /zuul/events/connection/github/election
2025-10-28 15:33:09,926 zuul.RendezvousElection          DEBUG    Acquiring lock for /zuul/events/connection/gerrit/election
2025-10-28 15:33:09,927 zuul.Launcher                    DEBUG    Updating tenant tenant-one
2025-10-28 15:33:09,927 zuul.Launcher                    DEBUG    Wait for tenant-one read tenant lock
2025-10-28 15:33:09,943 zuul.RendezvousElection          INFO     Won election for /zuul/events/connection/github/election
2025-10-28 15:33:09,943 zuul.Scheduler-0                 DEBUG    Processing tenant management events in tenant-one
2025-10-28 15:33:09,944 zuul.Launcher                    DEBUG    Aquired tenant-one read tenant lock
2025-10-28 15:33:09,944 zuul.RendezvousElection          INFO     Won election for /zuul/events/connection/gerrit/election
2025-10-28 15:33:09,946 zuul.Scheduler.LayoutUpdate      DEBUG    Aquired tenant-one read tenant lock
2025-10-28 15:33:09,947 zuul.Scheduler.LayoutUpdate      DEBUG    Released tenant-one read tenant lock
2025-10-28 15:33:09,947 zuul.Scheduler-0                 DEBUG    Aquired tenant-one read tenant lock
2025-10-28 15:33:09,951 zuul.Launcher                    DEBUG    Loaded provider static-main
2025-10-28 15:33:09,951 zuul.Launcher                    DEBUG    Released tenant-one read tenant lock
2025-10-28 15:33:09,951 zuul.Scheduler-0                 DEBUG    Processing tenant trigger events in tenant-one
2025-10-28 15:33:09,952 zuul.QuotaCache                  DEBUG    Initialize cache at /zuul/endpoint/static/quota
2025-10-28 15:33:09,962 zuul.QuotaCache                  DEBUG    Cache at /zuul/endpoint/static/quota is ready
2025-10-28 15:33:09,963 zuul.static.static               DEBUG    Starting static endpoint
2025-10-28 15:33:09,967 zuul.Scheduler-0                 DEBUG    Processing pipeline check in tenant tenant-one
2025-10-28 15:33:09,969 zuul.Launcher                    DEBUG    Requested node <StaticProviderNode uuid=3e66e3b915185a66acc22d344ca48be2, label=debian-normal, state=building, provider=review.example.com%2Forg%2Fcommon-config/static-main>
2025-10-28 15:33:09,969 zuul.Launcher                    DEBUG    Checking for old images
2025-10-28 15:33:09,969 zuul.Launcher                    DEBUG    Checking for missing images
2025-10-28 15:33:09,969 zuul.Launcher                    DEBUG    Done checking for missing images
2025-10-28 15:33:09,969 zuul.Launcher                    DEBUG    Checking for missing uploads
2025-10-28 15:33:09,970 zuul.zk.ZooKeeper                ERROR    Exception loading ZKObject at /zuul/nodes/nodes/3e66e3b915185a66acc22d344ca48be2/assignment
2025-10-28 15:33:09,970 zuul.Scheduler-0                 ERROR    Exception loading ZKObject at /zuul/tenant/tenant-one/pipeline/check/status
2025-10-28 15:33:09,970 zuul.PipelineSummary             WARNING  No pipeline summary found (may not be created yet)
2025-10-28 15:33:09,971 zuul.Scheduler-0                 DEBUG    Processing management event <zuul.model.PipelinePostConfigEvent object at 0x7f68dfe4aa90>
2025-10-28 15:33:09,973 zuul.Pipeline.tenant-one.check   DEBUG    Starting queue processor: check
2025-10-28 15:33:09,973 zuul.Pipeline.tenant-one.check   DEBUG    Finished queue processor: check (changed: False)
2025-10-28 15:33:09,977 zuul.Scheduler-0                 DEBUG    Processing pipeline gate in tenant tenant-one
2025-10-28 15:33:09,985 zuul.Scheduler-0                 ERROR    Exception loading ZKObject at /zuul/tenant/tenant-one/pipeline/gate/status
2025-10-28 15:33:09,985 zuul.PipelineSummary             WARNING  No pipeline summary found (may not be created yet)
2025-10-28 15:33:09,987 zuul.Scheduler-0                 DEBUG    Processing management event <zuul.model.PipelinePostConfigEvent object at 0x7f68df159410>
2025-10-28 15:33:09,988 zuul.Pipeline.tenant-one.gate    DEBUG    Starting queue processor: gate
2025-10-28 15:33:09,988 zuul.Pipeline.tenant-one.gate    DEBUG    Finished queue processor: gate (changed: False)
2025-10-28 15:33:09,994 zuul.Scheduler-0                 DEBUG    Processing pipeline post in tenant tenant-one
2025-10-28 15:33:09,995 zuul.Scheduler-0                 DEBUG    Starting semaphore cleanup
2025-10-28 15:33:10,005 zuul.Scheduler-0                 ERROR    Exception loading ZKObject at /zuul/tenant/tenant-one/pipeline/post/status
2025-10-28 15:33:10,005 zuul.PipelineSummary             WARNING  No pipeline summary found (may not be created yet)
2025-10-28 15:33:10,006 zuul.Scheduler-0                 DEBUG    Starting build request cleanup
2025-10-28 15:33:10,006 zuul.Scheduler-0                 DEBUG    Finished build request cleanup
2025-10-28 15:33:10,007 zuul.Scheduler-0                 DEBUG    Processing management event <zuul.model.PipelinePostConfigEvent object at 0x7f68e6b09390>
2025-10-28 15:33:10,008 zuul.Scheduler-0                 DEBUG    Starting node request cleanup
2025-10-28 15:33:10,009 zuul.Pipeline.tenant-one.post    DEBUG    Starting queue processor: post
2025-10-28 15:33:10,009 zuul.Pipeline.tenant-one.post    DEBUG    Finished queue processor: post (changed: False)
2025-10-28 15:33:10,023 zuul.Launcher                    ERROR    Exception loading ZKObject at /zuul/nodes/nodes/3e66e3b915185a66acc22d344ca48be2/assignment
2025-10-28 15:33:10,023 zuul.Launcher                    DEBUG    Building node <StaticProviderNode uuid=3e66e3b915185a66acc22d344ca48be2, label=debian-normal, state=building, provider=review.example.com%2Forg%2Fcommon-config/static-main>
2025-10-28 15:33:10,023 zuul.Launcher                    DEBUG    Node <StaticProviderNode uuid=3e66e3b915185a66acc22d344ca48be2, label=debian-normal, state=building, provider=review.example.com%2Forg%2Fcommon-config/static-main> external id None
2025-10-28 15:33:10,023 zuul.Launcher                    DEBUG    Submitted nodescan request for 198.51.100.1 queue length 1
2025-10-28 15:33:10,024 zuul.Scheduler-0                 DEBUG    Processing pipeline tag in tenant tenant-one
2025-10-28 15:33:10,027 zuul.Scheduler-0                 ERROR    Exception loading ZKObject at /zuul/tenant/tenant-one/pipeline/tag/status
2025-10-28 15:33:10,027 zuul.PipelineSummary             WARNING  No pipeline summary found (may not be created yet)
2025-10-28 15:33:10,031 zuul.Scheduler-0                 DEBUG    Processing management event <zuul.model.PipelinePostConfigEvent object at 0x7f69917ea390>
2025-10-28 15:33:10,037 zuul.Pipeline.tenant-one.tag     DEBUG    Starting queue processor: tag
2025-10-28 15:33:10,038 zuul.Pipeline.tenant-one.tag     DEBUG    Finished queue processor: tag (changed: False)
2025-10-28 15:33:10,047 zuul.Scheduler-0                 DEBUG    Released tenant-one read tenant lock
2025-10-28 15:33:10,048 zuul.Scheduler-0                 DEBUG    Run handler sleeping
2025-10-28 15:33:10,048 zuul.Scheduler-0                 DEBUG    Run handler awake
2025-10-28 15:33:10,058 apscheduler.scheduler            INFO     Added job "TestScheduler._runSemaphoreCleanup" to job store "default"
2025-10-28 15:33:10,058 apscheduler.scheduler            INFO     Added job "TestScheduler._runBuildRequestCleanup" to job store "default"
2025-10-28 15:33:10,058 apscheduler.scheduler            INFO     Added job "TestScheduler._runMergeRequestCleanup" to job store "default"
2025-10-28 15:33:10,058 apscheduler.scheduler            INFO     Added job "TestScheduler._runConnectionCleanup" to job store "default"
2025-10-28 15:33:10,058 apscheduler.scheduler            INFO     Added job "TestScheduler._runGeneralCleanup" to job store "default"
2025-10-28 15:33:10,058 apscheduler.scheduler            DEBUG    Looking for jobs to run
2025-10-28 15:33:10,059 apscheduler.scheduler            DEBUG    Next wakeup is due at 2025-10-28 15:33:51.230777+00:00 (in 41.171757 seconds)
2025-10-28 15:33:10,060 zuul.Scheduler-0                 DEBUG    Processing tenant management events in tenant-one
2025-10-28 15:33:10,064 zuul.Scheduler-0                 DEBUG    Aquired tenant-one read tenant lock
2025-10-28 15:33:10,071 zuul.Scheduler-0                 DEBUG    Processing tenant trigger events in tenant-one
2025-10-28 15:33:10,085 zuul.Launcher                    DEBUG    Added ssh host key: fake key
2025-10-28 15:33:10,085 zuul.Launcher                    DEBUG    Nodescan request complete with 1 keys, 1 initial connection attempts, 0 key connection failures, 0 key negotiation failures in 0 seconds
2025-10-28 15:33:10,121 zuul.Launcher                    DEBUG    Marking node <StaticProviderNode uuid=3e66e3b915185a66acc22d344ca48be2, label=debian-normal, state=ready, provider=review.example.com%2Forg%2Fcommon-config/static-main> as ready
2025-10-28 15:33:10,126 zuul.test                        ERROR    Exception loading ZKObject at /zuul/nodes/nodes/3e66e3b915185a66acc22d344ca48be2/assignment
2025-10-28 15:33:10,132 zuul.Scheduler-0                 DEBUG    Processing pipeline check in tenant tenant-one
2025-10-28 15:33:10,136 zuul.Scheduler-0                 DEBUG    No events to process for pipeline check in tenant tenant-one
2025-10-28 15:33:10,137 opentelemetry.attributes         WARNING  Invalid type NoneType for attribute 'request_uuid' value. Expected one of ['bool', 'str', 'bytes', 'int', 'float'] or a sequence of those types
2025-10-28 15:33:10,137 opentelemetry.attributes         WARNING  Invalid type NoneType for attribute 'zuul_event_id' value. Expected one of ['bool', 'str', 'bytes', 'int', 'float'] or a sequence of those types
2025-10-28 15:33:10,141 zuul.test                        ERROR    Exception saving ZKObject <StaticProviderNode uuid=3e66e3b915185a66acc22d344ca48be2, label=debian-normal, state=used, provider=review.example.com%2Forg%2Fcommon-config/static-main> at /zuul/nodes/nodes/3e66e3b915185a66acc22d344ca48be2
2025-10-28 15:33:10,144 zuul.Scheduler-0                 DEBUG    Processing pipeline gate in tenant tenant-one
2025-10-28 15:33:10,146 zuul.test                        DEBUG    Assert final state
2025-10-28 15:33:10,781 zuul.Launcher                    DEBUG    Provider endpoint quota limits for static-main: {}
2025-10-28 15:33:10,808 zuul.Scheduler-0                 DEBUG    No events to process for pipeline gate in tenant tenant-one
2025-10-28 15:33:10,821 zuul.test                        DEBUG    Leaked git repo object: 0x7f69962ac910 <git.repo.base.Repo '/tmp/zuul-test/tmpta4l5rkt/zuul-test/upstream/gh/project/.git'>
2025-10-28 15:33:10,821 zuul.test                        DEBUG    Leaked git repo object: 0x7f693053d550 <git.repo.base.Repo '/tmp/zuul-test/tmpta4l5rkt/zuul-test/upstream/gh/project1/.git'>
2025-10-28 15:33:10,821 zuul.test                        DEBUG    Leaked git repo object: 0x7f6990149650 <git.repo.base.Repo '/tmp/zuul-test/tmpta4l5rkt/zuul-test/upstream/gh/project1/.git'>
2025-10-28 15:33:10,821 zuul.test                        DEBUG    Leaked git repo object: 0x7f6995fd5550 <git.repo.base.Repo '/tmp/zuul-test/tmpta4l5rkt/zuul-test/upstream/gh/project1/.git'>
2025-10-28 15:33:10,821 zuul.test                        DEBUG    Leaked git repo object: 0x7f6990800ad0 <git.repo.base.Repo '/tmp/zuul-test/tmpta4l5rkt/zuul-test/upstream/gh/project1/.git'>
2025-10-28 15:33:10,838 zuul.test                        DEBUG    Leaked git repo object: 0x7f6973f91ad0 <git.repo.base.Repo '/tmp/zuul-test/tmp9trmo7ep/zuul-test/upstream/org/project/.git'>
2025-10-28 15:33:10,841 zuul.test                        DEBUG    Leaked git repo object: 0x7f6997d59e50 <git.repo.base.Repo '/tmp/zuul-test/tmpo3z8xhax/zuul-test/upstream/org/project5/.git'>
2025-10-28 15:33:10,921 zuul.test                        DEBUG    Leaked git repo object: 0x7f68e3e480d0 <git.repo.base.Repo '/tmp/zuul-test/tmpn62y_4qp/zuul-test/upstream/org/project/.git'>
2025-10-28 15:33:10,940 zuul.Launcher                    DEBUG    [req: dne] Deallocating node <StaticProviderNode uuid=3e66e3b915185a66acc22d344ca48be2, label=debian-normal, state=ready, provider=review.example.com%2Forg%2Fcommon-config/static-main> from missing request dne
2025-10-28 15:33:10,945 zuul.Scheduler-0                 DEBUG    Processing pipeline post in tenant tenant-one
2025-10-28 15:33:10,951 zuul.Scheduler-0                 DEBUG    No events to process for pipeline post in tenant tenant-one
2025-10-28 15:33:10,958 zuul.Scheduler-0                 DEBUG    Processing pipeline tag in tenant tenant-one
2025-10-28 15:33:10,968 zuul.test                        DEBUG    Shutting down after tests
2025-10-28 15:33:10,968 zuul.ExecutorServer              DEBUG    No running builds to release
2025-10-28 15:33:10,968 zuul.ExecutorClient              DEBUG    Stopping
2025-10-28 15:33:10,968 zuul.ExecutorServer              DEBUG    Stopping executor
2025-10-28 15:33:10,971 zuul.test.FakeGerritConnection   DEBUG    Stopping Gerrit Connection/Watchers
2025-10-28 15:33:10,971 zuul.ComponentRegistry           DEBUG    Registry <zuul.zk.components.ComponentRegistry object at 0x7f6998b31810> got event CHANGED for executor np6bc1754cc6fe40000000000
2025-10-28 15:33:10,971 zuul.ComponentRegistry           INFO     Component executor np6bc1754cc6fe40000000000 updated: {'accepting_work': True, 'allow_unzoned': True, 'hostname': 'np6bc1754cc6fe4', 'kind': 'executor', 'model_api': 36, 'process_merge_jobs': True, 'state': 'stopped', 'version': '13.0.2.dev15 18a7e5884', 'zone': None}
2025-10-28 15:33:10,971 zuul.RendezvousElection          DEBUG    Election winner for /zuul/events/connection/github/election is <SchedulerComponent {'hostname': 'np6bc1754cc6fe4', 'state': 'running', 'kind': 'scheduler', 'version': '13.0.2.dev15 18a7e5884', 'model_api': 36}>
2025-10-28 15:33:10,971 zuul.RendezvousElection          DEBUG    Election winner for /zuul/events/connection/gerrit/election is <SchedulerComponent {'hostname': 'np6bc1754cc6fe4', 'state': 'running', 'kind': 'scheduler', 'version': '13.0.2.dev15 18a7e5884', 'model_api': 36}>
2025-10-28 15:33:10,972 zuul.Scheduler-0                 DEBUG    No events to process for pipeline tag in tenant tenant-one
2025-10-28 15:33:10,973 zuul.Scheduler-0                 DEBUG    Released tenant-one read tenant lock
2025-10-28 15:33:10,974 zuul.Scheduler-0                 DEBUG    Run handler sleeping
2025-10-28 15:33:11,192 zuul.TimerDriver                 DEBUG    Stopping timer driver
2025-10-28 15:33:11,192 zuul.TimerDriver                 DEBUG    Stopping apscheduler
2025-10-28 15:33:11,192 apscheduler.scheduler            INFO     Scheduler has been shut down
2025-10-28 15:33:11,193 apscheduler.scheduler            DEBUG    Looking for jobs to run
2025-10-28 15:33:11,193 apscheduler.scheduler            DEBUG    No jobs; waiting until a job is added
2025-10-28 15:33:11,193 zuul.TimerDriver                 DEBUG    Stopped apscheduler
2025-10-28 15:33:11,193 zuul.TimerDriver                 DEBUG    Stopped timer driver
2025-10-28 15:33:11,193 zuul.CommandSocket               DEBUG    Accepted socket connection <socket.socket fd=39, family=1, type=1, proto=0, laddr=/tmp/zuul-test/tmpqh2ozn2c/zuul-test/executor.socket>
2025-10-28 15:33:11,194 zuul.CommandSocket               DEBUG    Received b'_stop' from socket
2025-10-28 15:33:11,195 zuul.ExecutorServer              DEBUG    Stopping base merge server
2025-10-28 15:33:11,195 zuul.ExecutorServer              DEBUG    Stopped base merge server
2025-10-28 15:33:11,195 zuul.ExecutorServer              DEBUG    Stopped executor
2025-10-28 15:33:11,195 zuul.ExecutorServer              DEBUG    Joining executor
2025-10-28 15:33:11,195 zuul.ExecutorServer              DEBUG    Joining base merge server
2025-10-28 15:33:11,199 zuul.zk.base.ZooKeeperClient     DEBUG    ZooKeeper connection (session: 0x0): LOST
2025-10-28 15:33:11,199 zuul.ExecutorServer              DEBUG    Joined base merge server
2025-10-28 15:33:11,199 zuul.ExecutorServer              DEBUG    Joined executor
2025-10-28 15:33:11,199 zuul.Launcher                    DEBUG    Stopping launcher
2025-10-28 15:33:11,202 zuul.CommandSocket               DEBUG    Accepted socket connection <socket.socket fd=74, family=1, type=1, proto=0, laddr=/tmp/zuul-test/tmpqh2ozn2c/zuul-test/launcher-0.socket>
2025-10-28 15:33:11,202 zuul.CommandSocket               DEBUG    Received b'_stop' from socket
2025-10-28 15:33:11,202 zuul.Launcher                    DEBUG    Stopping stats thread
2025-10-28 15:33:11,202 zuul.Launcher                    DEBUG    Stopping cleanup worker
2025-10-28 15:33:11,202 zuul.Launcher                    DEBUG    Joining cleanup thread
2025-10-28 15:33:11,202 zuul.Launcher                    DEBUG    Joined cleanup thread
2025-10-28 15:33:11,202 zuul.TimerDriver                 DEBUG    Stopping timer driver
2025-10-28 15:33:11,202 zuul.TimerDriver                 DEBUG    Stopping apscheduler
2025-10-28 15:33:11,202 apscheduler.scheduler            INFO     Scheduler has been shut down
2025-10-28 15:33:11,202 apscheduler.scheduler            DEBUG    Looking for jobs to run
2025-10-28 15:33:11,202 apscheduler.scheduler            DEBUG    No jobs; waiting until a job is added
2025-10-28 15:33:11,203 zuul.TimerDriver                 DEBUG    Stopped apscheduler
2025-10-28 15:33:11,203 zuul.TimerDriver                 DEBUG    Stopped timer driver
2025-10-28 15:33:11,203 zuul.static.static               DEBUG    Stopping static endpoint
2025-10-28 15:33:11,203 zuul.Launcher                    DEBUG    Stopped launcher
2025-10-28 15:33:11,203 zuul.Launcher                    DEBUG    Joining launcher
2025-10-28 15:33:11,203 zuul.zk.base.ZooKeeperClient     DEBUG    ZooKeeper connection (session: 0x0): LOST
2025-10-28 15:33:11,204 zuul.Launcher                    DEBUG    Joined launcher
2025-10-28 15:33:11,204 zuul.Scheduler-0                 DEBUG    Stopping scheduler
2025-10-28 15:33:11,204 zuul.Scheduler-0                 DEBUG    Stopping apscheduler
2025-10-28 15:33:11,204 apscheduler.scheduler            INFO     Scheduler has been shut down
2025-10-28 15:33:11,204 apscheduler.scheduler            DEBUG    Looking for jobs to run
2025-10-28 15:33:11,204 apscheduler.scheduler            DEBUG    No jobs; waiting until a job is added
2025-10-28 15:33:11,204 zuul.Scheduler-0                 DEBUG    Run handler stopping
2025-10-28 15:33:11,204 zuul.Scheduler-0                 DEBUG    Waiting for main thread
2025-10-28 15:33:11,205 zuul.Scheduler-0                 DEBUG    Stopping nodepool
2025-10-28 15:33:11,205 zuul.nodepool                    DEBUG    Stopping
2025-10-28 15:33:11,205 zuul.Scheduler-0                 DEBUG    Stopping connections
2025-10-28 15:33:11,206 zuul.Scheduler-0                 DEBUG    Waiting for layout update thread
2025-10-28 15:33:11,206 zuul.SQLConnection               DEBUG    Stopping SQL connection database
2025-10-28 15:33:11,206 zuul.test.FakeGerritConnection   DEBUG    Stopping Gerrit Connection/Watchers
2025-10-28 15:33:11,206 zuul.GerritConnection.poller     DEBUG    Stopping watcher
2025-10-28 15:33:11,207 zuul.RendezvousElection          INFO     Finished term for /zuul/events/connection/gerrit/election
2025-10-28 15:33:11,683 zuul.RendezvousElection          INFO     Finished term for /zuul/events/connection/github/election
2025-10-28 15:33:11,684 zuul.TimerDriver                 DEBUG    Stopping timer driver
2025-10-28 15:33:11,684 zuul.TimerDriver                 DEBUG    Stopping apscheduler
2025-10-28 15:33:11,684 apscheduler.scheduler            INFO     Scheduler has been shut down
2025-10-28 15:33:11,684 zuul.TimerDriver                 DEBUG    Timer election tenure ended
2025-10-28 15:33:11,684 apscheduler.scheduler            DEBUG    Looking for jobs to run
2025-10-28 15:33:11,684 apscheduler.scheduler            DEBUG    No jobs; waiting until a job is added
2025-10-28 15:33:11,684 zuul.TimerDriver                 DEBUG    Stopped apscheduler
2025-10-28 15:33:11,684 zuul.TimerDriver                 DEBUG    Stopping election
2025-10-28 15:33:11,684 zuul.TimerDriver                 DEBUG    Stopped election
2025-10-28 15:33:11,684 zuul.TimerDriver                 DEBUG    Stopping election thread
2025-10-28 15:33:11,684 zuul.TimerDriver                 DEBUG    Exiting timer election loop
2025-10-28 15:33:11,684 zuul.TimerDriver                 DEBUG    Stopped election thread
2025-10-28 15:33:11,684 zuul.TimerDriver                 DEBUG    Stopped timer driver
2025-10-28 15:33:11,684 zuul.Scheduler-0                 DEBUG    Stopping stats thread
2025-10-28 15:33:11,684 zuul.Scheduler-0                 DEBUG    Stopping command socket
2025-10-28 15:33:11,685 zuul.CommandSocket               DEBUG    Accepted socket connection <socket.socket fd=7, family=1, type=1, proto=0, laddr=/tmp/zuul-test/tmpqh2ozn2c/zuul-test/scheduler-0.socket>
2025-10-28 15:33:11,685 zuul.CommandSocket               DEBUG    Received b'_stop' from socket
2025-10-28 15:33:11,685 zuul.Scheduler-0                 DEBUG    Stopping timedb thread
2025-10-28 15:33:11,685 zuul.Scheduler-0                 DEBUG    Stopping monitoring server
2025-10-28 15:33:11,685 zuul.Scheduler-0                 DEBUG    Disconnecting from ZooKeeper
2025-10-28 15:33:11,686 zuul.zk.base.ZooKeeperClient     DEBUG    ZooKeeper connection (session: 0x0): LOST
2025-10-28 15:33:11,686 zuul.Scheduler-0                 DEBUG    Stopping tracing
2025-10-28 15:33:11,686 zuul.ExecutorClient              DEBUG    Stopping
2025-10-28 15:33:11,758 zuul.zk.base.ZooKeeperClient     DEBUG    ZooKeeper connection (session: 0x0): LOST
2025-10-28 15:33:11,758 zuul.test                        DEBUG    Build history: no builds ran
2025-10-28 15:33:11,758 zuul.test.MySQLSchemaFixture     DEBUG    Deleting database 127.0.0.1:3306:DWJwsoyk_8564
}}}

Traceback (most recent call last):
  File "/home/zuul/src/opendev.org/zuul/zuul/tests/unit/test_static_driver.py", line 403, in test_static_deregistration_in_use
    with main.activeContext(ctx):
  File "/usr/lib/python3.11/contextlib.py", line 144, in __exit__
    next(self.gen)
  File "/home/zuul/src/opendev.org/zuul/zuul/zuul/zk/zkobject.py", line 236, in activeContext
    self._save(context, serial)
  File "/home/zuul/src/opendev.org/zuul/zuul/zuul/zk/zkobject.py", line 481, in _save
    zstat = self._retry(context, self._retryableSave,
            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/zuul/src/opendev.org/zuul/zuul/zuul/zk/zkobject.py", line 370, in _retry
    return kazoo_retry(func, *args, **kw)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/zuul/src/opendev.org/zuul/zuul/.nox/tests-3-11/lib/python3.11/site-packages/kazoo/retry.py", line 126, in __call__
    return func(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^
  File "/home/zuul/src/opendev.org/zuul/zuul/zuul/zk/zkobject.py", line 453, in _retryableSave
    stream.write(data)
  File "/home/zuul/src/opendev.org/zuul/zuul/zuul/zk/sharding.py", line 78, in write
    self.zstat = self.client.set(self.path, data,
                 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/zuul/src/opendev.org/zuul/zuul/.nox/tests-3-11/lib/python3.11/site-packages/kazoo/client.py", line 1359, in set
    return self.set_async(path, value, version).get()
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/zuul/src/opendev.org/zuul/zuul/.nox/tests-3-11/lib/python3.11/site-packages/kazoo/handlers/utils.py", line 86, in get
    raise self._exception
kazoo.exceptions.BadVersionError

Test Group/Test case	Count	Pass	Fail	Error	Skip	View
tests.unit.test_static_driver.TestStaticDriver	10	9	1	0	0	Detail
test_static_failure	pass [x] pt1.1: tests.unit.test_static_driver.TestStaticDriver.test_static_failure
test_static_node_lifecycle	pass [x] pt1.2: tests.unit.test_static_driver.TestStaticDriver.test_static_node_lifecycle
test_static_subnodes	pass [x] pt1.3: tests.unit.test_static_driver.TestStaticDriver.test_static_subnodes
test_static_subnodes_deregistration	pass [x] pt1.4: tests.unit.test_static_driver.TestStaticDriver.test_static_subnodes_deregistration
test_static_deregistration	pass [x] pt1.5: tests.unit.test_static_driver.TestStaticDriver.test_static_deregistration
test_static_deregistration_in_use	fail [x] ft1.6: tests.unit.test_static_driver.TestStaticDriver.test_static_deregistration_in_usetesttools.testresult.real._StringException: dburi: {{{mariadb+pymysql://DWJwsoyk_8564:c830e236b9ce4e14815a263aff4a0c9f@127.0.0.1:3306/DWJwsoyk_8564}}} logging: {{{ 2025-10-28 15:33:08,612 zuul.test.MySQLSchemaFixture DEBUG Creating database 127.0.0.1:3306:DWJwsoyk_8564 2025-10-28 15:33:08,620 git.util DEBUG sys.platform='linux', git_executable='git' 2025-10-28 15:33:08,628 git.util DEBUG sys.platform='linux', git_executable='git' 2025-10-28 15:33:08,640 git.util DEBUG sys.platform='linux', git_executable='git' 2025-10-28 15:33:08,647 git.util DEBUG sys.platform='linux', git_executable='git' 2025-10-28 15:33:08,666 zuul.zk.base.ZooKeeperClient DEBUG ZooKeeper connection (session: 0x10000076ee72063): CONNECTED 2025-10-28 15:33:08,670 zuul.KeyStorage INFO Created key at /keystorage2/tenant/tenant-one/ssh 2025-10-28 15:33:08,674 zuul.KeyStorage INFO Created key at /keystorage/gerrit/org/org%2Fcommon-config/secrets 2025-10-28 15:33:08,674 zuul.KeyStorage INFO Created key at /keystorage/gerrit/org/org%2Fcommon-config/ssh 2025-10-28 15:33:08,676 zuul.KeyStorage INFO Created key at /keystorage/gerrit/org/org%2Fproject/secrets 2025-10-28 15:33:08,676 zuul.KeyStorage INFO Created key at /keystorage/gerrit/org/org%2Fproject/ssh 2025-10-28 15:33:08,676 zuul.TimerDriver DEBUG Starting apscheduler 2025-10-28 15:33:08,676 apscheduler.scheduler INFO Scheduler started 2025-10-28 15:33:08,677 apscheduler.scheduler DEBUG Looking for jobs to run 2025-10-28 15:33:08,677 apscheduler.scheduler DEBUG No jobs; waiting until a job is added 2025-10-28 15:33:08,677 Zuul.CapabilitiesRegistry DEBUG Capabilities "job_history" updated 2025-10-28 15:33:08,677 zuul.BubblewrapDriver DEBUG Initializing bubblewrap with oom_score_adj starting: 0, final: 200 2025-10-28 15:33:08,678 zuul.BubblewrapExecutionContext DEBUG Bubblewrap command: setpriv --ambient-caps -all choom -n 200 -- bwrap --dir /tmp --tmpfs /tmp --dir /var --dir /var/tmp --dir /run/user/1000 --ro-bind /usr /usr --ro-bind /lib /lib --ro-bind /bin /bin --ro-bind /sbin /sbin --ro-bind /etc/ld.so.cache /etc/ld.so.cache --ro-bind /etc/resolv.conf /etc/resolv.conf --ro-bind /etc/hosts /etc/hosts --ro-bind /etc/localtime /etc/localtime --ro-bind /dev/null /dev/null --bind /tmp /tmp --tmpfs /tmp/tmp --proc /proc --dev /dev --chdir /tmp --unshare-all --share-net --die-with-parent --uid 1000 --gid 1000 --file 29 /etc/passwd --file 31 /etc/group --ro-bind /lib64 /lib64 --ro-bind /etc/nsswitch.conf /etc/nsswitch.conf --ro-bind /etc/alternatives /etc/alternatives --ro-bind /etc/ssl/certs /etc/ssl/certs --ro-bind /etc/subuid /etc/subuid 2025-10-28 15:33:08,686 zuul.github.graphql DEBUG Loading prepared graphql queries 2025-10-28 15:33:08,686 zuul.test.FakeGithubClientManager INFO Authing to GitHub 2025-10-28 15:33:08,688 zuul.ExecutorQueue DEBUG Creating executor queue at root /zuul/executor/unzoned 2025-10-28 15:33:08,695 zuul.zk.ZooKeeper DEBUG Initialize cache at /zuul/executor/unzoned 2025-10-28 15:33:08,698 zuul.zk.ZooKeeper DEBUG Cache at /zuul/executor/unzoned is ready 2025-10-28 15:33:08,704 zuul.zk.ZooKeeper DEBUG Initialize cache at /zuul/merger 2025-10-28 15:33:08,707 zuul.zk.ZooKeeper DEBUG Cache at /zuul/merger is ready 2025-10-28 15:33:08,707 opentelemetry.trace WARNING Overriding of current TracerProvider is not allowed 2025-10-28 15:33:08,714 zuul.zk.base.ZooKeeperClient DEBUG ZooKeeper connection (session: 0x10000076ee72064): CONNECTED 2025-10-28 15:33:08,716 zuul.zk.ZooKeeper DEBUG Initialize cache at /zuul/merger 2025-10-28 15:33:08,719 zuul.zk.ZooKeeper DEBUG Cache at /zuul/merger is ready 2025-10-28 15:33:08,720 zuul.zk.ZooKeeper DEBUG Initialize cache at /keystorage-oidc 2025-10-28 15:33:08,721 zuul.zk.ZooKeeper DEBUG Cache at /keystorage-oidc is ready 2025-10-28 15:33:08,721 zuul.Component INFO Registering component in ZooKeeper /zuul/components/executor/np6bc1754cc6fe4 2025-10-28 15:33:08,724 zuul.ComponentRegistry INFO Noticed new executor component np6bc1754cc6fe40000000000 2025-10-28 15:33:08,725 zuul.ComponentRegistry DEBUG Registry <zuul.zk.components.ComponentRegistry object at 0x7f6998b31810> got event None for executor np6bc1754cc6fe40000000000 2025-10-28 15:33:08,725 zuul.ComponentRegistry INFO Component executor np6bc1754cc6fe40000000000 updated: {'accepting_work': False, 'allow_unzoned': False, 'hostname': 'np6bc1754cc6fe4', 'kind': 'executor', 'model_api': 36, 'process_merge_jobs': False, 'state': 'stopped', 'version': '13.0.2.dev15 18a7e5884', 'zone': None} 2025-10-28 15:33:08,728 zuul.ComponentRegistry INFO System minimum data model version 36; this component 36 2025-10-28 15:33:08,728 opentelemetry.trace WARNING Overriding of current TracerProvider is not allowed 2025-10-28 15:33:08,729 zuul.ComponentRegistry DEBUG Registry <zuul.zk.components.ComponentRegistry object at 0x7f6998b31810> got event CHANGED for executor np6bc1754cc6fe40000000000 2025-10-28 15:33:08,729 zuul.ComponentRegistry INFO Component executor np6bc1754cc6fe40000000000 updated: {'accepting_work': False, 'allow_unzoned': False, 'hostname': 'np6bc1754cc6fe4', 'kind': 'executor', 'model_api': 36, 'process_merge_jobs': False, 'state': 'stopped', 'version': '13.0.2.dev15 18a7e5884', 'zone': None} 2025-10-28 15:33:08,730 zuul.ComponentRegistry DEBUG Registry <zuul.zk.components.ComponentRegistry object at 0x7f6998b31810> got event CHANGED for executor np6bc1754cc6fe40000000000 2025-10-28 15:33:08,730 zuul.ComponentRegistry INFO Component executor np6bc1754cc6fe40000000000 updated: {'accepting_work': False, 'allow_unzoned': True, 'hostname': 'np6bc1754cc6fe4', 'kind': 'executor', 'model_api': 36, 'process_merge_jobs': False, 'state': 'stopped', 'version': '13.0.2.dev15 18a7e5884', 'zone': None} 2025-10-28 15:33:08,730 zuul.ExecutorServer INFO Starting executor (hostname: np6bc1754cc6fe4) in unpaused mode 2025-10-28 15:33:08,731 zuul.ComponentRegistry DEBUG Registry <zuul.zk.components.ComponentRegistry object at 0x7f6998b31810> got event CHANGED for executor np6bc1754cc6fe40000000000 2025-10-28 15:33:08,731 zuul.ComponentRegistry INFO Component executor np6bc1754cc6fe40000000000 updated: {'accepting_work': True, 'allow_unzoned': True, 'hostname': 'np6bc1754cc6fe4', 'kind': 'executor', 'model_api': 36, 'process_merge_jobs': False, 'state': 'stopped', 'version': '13.0.2.dev15 18a7e5884', 'zone': None} 2025-10-28 15:33:08,731 zuul.ComponentRegistry DEBUG Registry <zuul.zk.components.ComponentRegistry object at 0x7f6998b31810> got event CHANGED for executor np6bc1754cc6fe40000000000 2025-10-28 15:33:08,731 zuul.ComponentRegistry INFO Component executor np6bc1754cc6fe40000000000 updated: {'accepting_work': True, 'allow_unzoned': True, 'hostname': 'np6bc1754cc6fe4', 'kind': 'executor', 'model_api': 36, 'process_merge_jobs': True, 'state': 'stopped', 'version': '13.0.2.dev15 18a7e5884', 'zone': None} 2025-10-28 15:33:08,732 zuul.ExecutorQueue DEBUG Creating executor queue at root /zuul/executor/unzoned 2025-10-28 15:33:08,733 zuul.zk.ZooKeeper DEBUG Initialize cache at /zuul/executor/unzoned 2025-10-28 15:33:08,736 zuul.zk.ZooKeeper DEBUG Cache at /zuul/executor/unzoned is ready 2025-10-28 15:33:08,736 zuul.ExecutorServer DEBUG Starting merger 2025-10-28 15:33:08,736 zuul.ExecutorServer WARNING Multiprocessing context has already been set 2025-10-28 15:33:08,737 zuul.ExecutorServer DEBUG Starting command processor 2025-10-28 15:33:08,737 zuul.ExecutorServer DEBUG Starting 4 update workers 2025-10-28 15:33:08,739 zuul.TimerDriver DEBUG Starting apscheduler 2025-10-28 15:33:08,739 apscheduler.scheduler INFO Scheduler started 2025-10-28 15:33:08,739 apscheduler.scheduler DEBUG Looking for jobs to run 2025-10-28 15:33:08,739 apscheduler.scheduler DEBUG No jobs; waiting until a job is added 2025-10-28 15:33:08,739 zuul.ComponentRegistry DEBUG Registry <zuul.zk.components.ComponentRegistry object at 0x7f6998b31810> got event CHANGED for executor np6bc1754cc6fe40000000000 2025-10-28 15:33:08,740 zuul.ComponentRegistry INFO Component executor np6bc1754cc6fe40000000000 updated: {'accepting_work': True, 'allow_unzoned': True, 'hostname': 'np6bc1754cc6fe4', 'kind': 'executor', 'model_api': 36, 'process_merge_jobs': True, 'state': 'running', 'version': '13.0.2.dev15 18a7e5884', 'zone': None} 2025-10-28 15:33:08,740 Zuul.CapabilitiesRegistry DEBUG Capabilities "job_history" updated 2025-10-28 15:33:08,740 zuul.BubblewrapDriver DEBUG Initializing bubblewrap with oom_score_adj starting: 0, final: 200 2025-10-28 15:33:08,741 zuul.BubblewrapExecutionContext DEBUG Bubblewrap command: setpriv --ambient-caps -all choom -n 200 -- bwrap --dir /tmp --tmpfs /tmp --dir /var --dir /var/tmp --dir /run/user/1000 --ro-bind /usr /usr --ro-bind /lib /lib --ro-bind /bin /bin --ro-bind /sbin /sbin --ro-bind /etc/ld.so.cache /etc/ld.so.cache --ro-bind /etc/resolv.conf /etc/resolv.conf --ro-bind /etc/hosts /etc/hosts --ro-bind /etc/localtime /etc/localtime --ro-bind /dev/null /dev/null --bind /tmp /tmp --tmpfs /tmp/tmp --proc /proc --dev /dev --chdir /tmp --unshare-all --share-net --die-with-parent --uid 1000 --gid 1000 --file 72 /etc/passwd --file 73 /etc/group --ro-bind /lib64 /lib64 --ro-bind /etc/nsswitch.conf /etc/nsswitch.conf --ro-bind /etc/alternatives /etc/alternatives --ro-bind /etc/ssl/certs /etc/ssl/certs --ro-bind /etc/subuid /etc/subuid 2025-10-28 15:33:08,749 opentelemetry.trace WARNING Overriding of current TracerProvider is not allowed 2025-10-28 15:33:08,756 zuul.zk.base.ZooKeeperClient DEBUG ZooKeeper connection (session: 0x10000076ee72065): CONNECTED 2025-10-28 15:33:08,757 zuul.Component INFO Registering component in ZooKeeper /zuul/components/launcher/launcher-0 2025-10-28 15:33:08,757 zuul.zk.ZooKeeper DEBUG Initialize cache at /zuul/nodeset 2025-10-28 15:33:08,757 zuul.ComponentRegistry INFO Noticed new launcher component launcher-00000000000 2025-10-28 15:33:08,758 zuul.ComponentRegistry DEBUG Registry <zuul.zk.components.ComponentRegistry object at 0x7f6998b31810> got event None for launcher launcher-00000000000 2025-10-28 15:33:08,758 zuul.ComponentRegistry INFO Component launcher launcher-00000000000 updated: {'connection_filter': None, 'hostname': 'launcher-0', 'kind': 'launcher', 'model_api': 36, 'state': 'stopped', 'version': '13.0.2.dev15 18a7e5884'} 2025-10-28 15:33:08,759 zuul.zk.ZooKeeper DEBUG Cache at /zuul/nodeset is ready 2025-10-28 15:33:08,759 zuul.zk.ZooKeeper DEBUG Initialize cache at /zuul/nodes 2025-10-28 15:33:08,761 zuul.zk.ZooKeeper DEBUG Cache at /zuul/nodes is ready 2025-10-28 15:33:08,762 zuul.zk.ZooKeeper DEBUG Initialize cache at /zuul/images 2025-10-28 15:33:08,764 zuul.zk.ZooKeeper DEBUG Cache at /zuul/images is ready 2025-10-28 15:33:08,764 zuul.zk.ZooKeeper DEBUG Initialize cache at /zuul/image-uploads 2025-10-28 15:33:08,765 zuul.zk.ZooKeeper DEBUG Cache at /zuul/image-uploads is ready 2025-10-28 15:33:08,765 zuul.Launcher DEBUG Cleaning up temp dir 2025-10-28 15:33:08,765 zuul.Launcher DEBUG Starting command processor 2025-10-28 15:33:08,766 zuul.Launcher DEBUG Starting nodescan worker 2025-10-28 15:33:08,766 zuul.Launcher DEBUG Starting launcher thread 2025-10-28 15:33:08,766 zuul.Launcher DEBUG Running stats election 2025-10-28 15:33:08,767 zuul.TimerDriver DEBUG Starting apscheduler 2025-10-28 15:33:08,767 apscheduler.scheduler INFO Scheduler started 2025-10-28 15:33:08,767 apscheduler.scheduler DEBUG Looking for jobs to run 2025-10-28 15:33:08,767 apscheduler.scheduler DEBUG No jobs; waiting until a job is added 2025-10-28 15:33:08,767 Zuul.CapabilitiesRegistry DEBUG Capabilities "job_history" updated 2025-10-28 15:33:08,767 zuul.BubblewrapDriver DEBUG Initializing bubblewrap with oom_score_adj starting: 0, final: 200 2025-10-28 15:33:08,769 zuul.Launcher DEBUG Launcher running 2025-10-28 15:33:08,769 zuul.ComponentRegistry DEBUG Registry <zuul.zk.components.ComponentRegistry object at 0x7f6998b31810> got event CHANGED for launcher launcher-00000000000 2025-10-28 15:33:08,769 zuul.ComponentRegistry INFO Component launcher launcher-00000000000 updated: {'connection_filter': None, 'hostname': 'launcher-0', 'kind': 'launcher', 'model_api': 36, 'state': 'running', 'version': '13.0.2.dev15 18a7e5884'} 2025-10-28 15:33:08,772 zuul.BubblewrapExecutionContext DEBUG Bubblewrap command: setpriv --ambient-caps -all choom -n 200 -- bwrap --dir /tmp --tmpfs /tmp --dir /var --dir /var/tmp --dir /run/user/1000 --ro-bind /usr /usr --ro-bind /lib /lib --ro-bind /bin /bin --ro-bind /sbin /sbin --ro-bind /etc/ld.so.cache /etc/ld.so.cache --ro-bind /etc/resolv.conf /etc/resolv.conf --ro-bind /etc/hosts /etc/hosts --ro-bind /etc/localtime /etc/localtime --ro-bind /dev/null /dev/null --bind /tmp /tmp --tmpfs /tmp/tmp --proc /proc --dev /dev --chdir /tmp --unshare-all --share-net --die-with-parent --uid 1000 --gid 1000 --file 68 /etc/passwd --file 64 /etc/group --ro-bind /lib64 /lib64 --ro-bind /etc/nsswitch.conf /etc/nsswitch.conf --ro-bind /etc/alternatives /etc/alternatives --ro-bind /etc/ssl/certs /etc/ssl/certs --ro-bind /etc/subuid /etc/subuid 2025-10-28 15:33:08,777 zuul.Launcher DEBUG Won stats election 2025-10-28 15:33:08,783 zuul.SQLConnection INFO Initializing SQL connection database (prefix: ) 2025-10-28 15:33:08,797 zuul.github.graphql DEBUG Loading prepared graphql queries 2025-10-28 15:33:08,798 zuul.test.FakeGithubClientManager INFO Authing to GitHub 2025-10-28 15:33:08,800 opentelemetry.trace WARNING Overriding of current TracerProvider is not allowed 2025-10-28 15:33:08,819 zuul.zk.base.ZooKeeperClient DEBUG ZooKeeper connection (session: 0x10000076ee72066): CONNECTED 2025-10-28 15:33:08,820 zuul.Component INFO Registering component in ZooKeeper /zuul/components/scheduler/np6bc1754cc6fe4 2025-10-28 15:33:08,822 zuul.ComponentRegistry INFO Noticed new scheduler component np6bc1754cc6fe40000000000 2025-10-28 15:33:08,823 zuul.ComponentRegistry DEBUG Registry <zuul.zk.components.ComponentRegistry object at 0x7f6998b31810> got event None for scheduler np6bc1754cc6fe40000000000 2025-10-28 15:33:08,824 zuul.ComponentRegistry INFO Component scheduler np6bc1754cc6fe40000000000 updated: {'hostname': 'np6bc1754cc6fe4', 'kind': 'scheduler', 'model_api': 36, 'state': 'stopped', 'version': '13.0.2.dev15 18a7e5884'} 2025-10-28 15:33:08,829 zuul.zk.ZooKeeper DEBUG Initialize cache at /keystorage-oidc 2025-10-28 15:33:08,831 zuul.zk.ZooKeeper DEBUG Cache at /keystorage-oidc is ready 2025-10-28 15:33:08,833 zuul.ExecutorQueue DEBUG Creating executor queue at root /zuul/executor/unzoned 2025-10-28 15:33:08,837 zuul.zk.ZooKeeper DEBUG Initialize cache at /zuul/executor/unzoned 2025-10-28 15:33:08,846 zuul.zk.ZooKeeper DEBUG Cache at /zuul/executor/unzoned is ready 2025-10-28 15:33:08,849 zuul.zk.ZooKeeper DEBUG Initialize cache at /zuul/merger 2025-10-28 15:33:08,870 zuul.zk.ZooKeeper DEBUG Cache at /zuul/merger is ready 2025-10-28 15:33:08,878 zuul.nodepool DEBUG Running nodepool watcher election 2025-10-28 15:33:08,879 zuul.TimerDriver DEBUG Starting timer election loop 2025-10-28 15:33:08,879 zuul.TimerDriver INFO Running timer election 2025-10-28 15:33:08,895 zuul.nodepool INFO Watching nodepool requests 2025-10-28 15:33:08,895 zuul.TimerDriver INFO Won timer election 2025-10-28 15:33:08,902 alembic.runtime.migration INFO Context impl MariaDBImpl. 2025-10-28 15:33:08,902 alembic.runtime.migration INFO Will assume non-transactional DDL. 2025-10-28 15:33:08,903 zuul.SQLConnection DEBUG Current migration revision: None 2025-10-28 15:33:08,984 alembic.runtime.migration INFO Context impl MariaDBImpl. 2025-10-28 15:33:08,984 alembic.runtime.migration INFO Will assume non-transactional DDL. 2025-10-28 15:33:08,990 alembic.runtime.migration INFO Running stamp_revision -> 6c1582c1d08c 2025-10-28 15:33:08,991 alembic.runtime.migration DEBUG new branch insert 6c1582c1d08c 2025-10-28 15:33:08,993 zuul.test.FakeGerritConnection DEBUG Starting Gerrit Connection/Watchers 2025-10-28 15:33:08,993 zuul.test.FakeGerritConnection DEBUG GET: http://localhost:52721/a/config/server/version 2025-10-28 15:33:08,994 responses INFO request.allowed-passthru 2025-10-28 15:33:08,994 urllib3.connectionpool DEBUG Starting new HTTP connection (1): localhost:52721 2025-10-28 15:33:08,995 zuul.test.FakeGerritConnection DEBUG Got GET /a/config/server/version 2025-10-28 15:33:08,995 zuul.test.FakeGerritConnection DEBUG "GET /a/config/server/version HTTP/1.1" 200 - 2025-10-28 15:33:08,997 urllib3.connectionpool DEBUG http://localhost:52721 "GET /a/config/server/version HTTP/1.1" 200 23 2025-10-28 15:33:08,997 zuul.GerritConnection.io DEBUG Received: 200 )]}' "3.0.0-some-stuff" 2025-10-28 15:33:08,997 zuul.test.FakeGerritConnection INFO Remote version is: 3.0.0-some-stuff (parsed as (3, 0, 0)) 2025-10-28 15:33:08,997 zuul.test.FakeGerritConnection DEBUG GET: http://localhost:52721/a/config/server/info 2025-10-28 15:33:08,997 responses INFO request.allowed-passthru 2025-10-28 15:33:08,997 urllib3.connectionpool DEBUG Resetting dropped connection: localhost 2025-10-28 15:33:08,999 zuul.test.FakeGerritConnection DEBUG Got GET /a/config/server/info 2025-10-28 15:33:08,999 zuul.test.FakeGerritConnection DEBUG "GET /a/config/server/info HTTP/1.1" 200 - 2025-10-28 15:33:08,999 urllib3.connectionpool DEBUG http://localhost:52721 "GET /a/config/server/info HTTP/1.1" 200 603 2025-10-28 15:33:08,999 zuul.GerritConnection.io DEBUG Received: 200 )]}' {"accounts": {"visibility": "ALL", "default_display_name": "FULL_NAME"}, "change": {"allow_blame": true, "disable_private_changes": true, "update_delay": 300, "mergeability_computation_behavior": "API_REF_UPDATED_AND_CHANGE_REINDEX", "enable_robot_comments": true, "conflicts_predicate_enabled": true}, "gerrit": {"all_projects": "All-Projects", "all_users": "All-Users", "doc_search": true}, "note_db_enabled": true, "sshd": {}, "suggest": {"from": 0}, "user": {"anonymous_coward_name": "Name of user not set"}, "receive": {"enable_signed_push": false}, "submit_requirement_dashboard_columns": []} 2025-10-28 15:33:08,999 zuul.test.FakeGerritConnection INFO Remote submitWholeTopic: False 2025-10-28 15:33:08,999 zuul.test.FakeGerritConnection DEBUG Creating Zookeeper branch cache 2025-10-28 15:33:09,024 zuul.BranchCache.gerrit ERROR Exception loading ZKObject at /zuul/cache/connection/gerrit/branches/data 2025-10-28 15:33:09,037 zuul.test.FakeGerritConnection INFO Creating Zookeeper event queue 2025-10-28 15:33:09,054 zuul.test.FakeGerritConnection DEBUG Creating Zookeeper change cache 2025-10-28 15:33:09,059 zuul.test.FakeGithubConnection INFO Starting GitHub connection: github 2025-10-28 15:33:09,059 zuul.test.FakeGithubClientManager INFO Authing to GitHub 2025-10-28 15:33:09,059 zuul.test.FakeGithubConnection DEBUG Creating Zookeeper branch cache 2025-10-28 15:33:09,062 zuul.BranchCache.github ERROR Exception loading ZKObject at /zuul/cache/connection/github/branches/data 2025-10-28 15:33:09,065 zuul.test.FakeGithubConnection DEBUG Creating Zookeeper event queue 2025-10-28 15:33:09,075 zuul.test.FakeGithubConnection DEBUG Creating Zookeeper change cache 2025-10-28 15:33:09,086 zuul.test.FakeGithubConnection INFO Starting event connector 2025-10-28 15:33:09,086 zuul.Scheduler-0 DEBUG Statsd enabled 2025-10-28 15:33:09,086 zuul.Scheduler-0 DEBUG Run handler sleeping 2025-10-28 15:33:09,086 zuul.Scheduler-0 DEBUG Run handler awake 2025-10-28 15:33:09,086 zuul.Scheduler-0 DEBUG Starting command processor 2025-10-28 15:33:09,087 zuul.Scheduler-0 DEBUG Running stats election 2025-10-28 15:33:09,087 apscheduler.scheduler INFO Scheduler started 2025-10-28 15:33:09,087 apscheduler.scheduler DEBUG Looking for jobs to run 2025-10-28 15:33:09,087 apscheduler.scheduler DEBUG No jobs; waiting until a job is added 2025-10-28 15:33:09,089 zuul.Scheduler-0 INFO Priming scheduler config 2025-10-28 15:33:09,089 zuul.ComponentRegistry DEBUG Registry <zuul.zk.components.ComponentRegistry object at 0x7f6998b31810> got event CHANGED for scheduler np6bc1754cc6fe40000000000 2025-10-28 15:33:09,089 zuul.ComponentRegistry INFO Component scheduler np6bc1754cc6fe40000000000 updated: {'hostname': 'np6bc1754cc6fe4', 'kind': 'scheduler', 'model_api': 36, 'state': 'initializing', 'version': '13.0.2.dev15 18a7e5884'} 2025-10-28 15:33:09,089 zuul.RendezvousElection DEBUG Election winner for /zuul/events/connection/github/election is None 2025-10-28 15:33:09,089 zuul.RendezvousElection DEBUG Election winner for /zuul/events/connection/gerrit/election is None 2025-10-28 15:33:09,094 zuul.Scheduler-0 DEBUG Won stats election 2025-10-28 15:33:09,096 zuul.Scheduler-0 INFO Creating initial system config 2025-10-28 15:33:09,096 zuul.ConfigLoader INFO Loading configuration from /tmp/zuul-test/tmpqh2ozn2c/zuul-test/config/tmp78f6l06z 2025-10-28 15:33:09,097 zuul.Scheduler-0 DEBUG Run handler sleeping 2025-10-28 15:33:09,101 zuul.Scheduler-0 DEBUG Run handler awake 2025-10-28 15:33:09,186 zuul.Scheduler-0 DEBUG Wait for tenant-one write tenant lock (id: None) 2025-10-28 15:33:09,193 zuul.Scheduler-0 DEBUG Aquired tenant-one write tenant lock (id: None) 2025-10-28 15:33:09,201 git.util DEBUG sys.platform='linux', git_executable='git' 2025-10-28 15:33:09,202 git.util DEBUG sys.platform='linux', git_executable='git' 2025-10-28 15:33:09,240 zuul.Scheduler-0 DEBUG Run handler sleeping 2025-10-28 15:33:09,242 zuul.test.FakeGerritConnection DEBUG Fetched 1 branches for org/project 2025-10-28 15:33:09,242 zuul.test.FakeGerritConnection INFO Got branches for org/project 2025-10-28 15:33:09,244 zuul.test.FakeGerritConnection DEBUG Fetched 1 branches for org/common-config 2025-10-28 15:33:09,245 zuul.test.FakeGerritConnection INFO Got branches for org/common-config 2025-10-28 15:33:09,248 zuul.test.FakeGerritConnection DEBUG GET: http://localhost:52721/a/projects/org%2Fproject/HEAD 2025-10-28 15:33:09,248 responses INFO request.allowed-passthru 2025-10-28 15:33:09,249 urllib3.connectionpool DEBUG Resetting dropped connection: localhost 2025-10-28 15:33:09,249 zuul.test.FakeGerritConnection DEBUG Got GET /a/projects/org%2Fproject/HEAD 2025-10-28 15:33:09,250 zuul.test.FakeGerritConnection DEBUG "GET /a/projects/org%2Fproject/HEAD HTTP/1.1" 200 - 2025-10-28 15:33:09,253 urllib3.connectionpool DEBUG http://localhost:52721 "GET /a/projects/org%2Fproject/HEAD HTTP/1.1" 200 24 2025-10-28 15:33:09,253 zuul.GerritConnection.io DEBUG Received: 200 )]}' "refs/heads/master" 2025-10-28 15:33:09,253 zuul.test.FakeGerritConnection INFO Got default branch for org/project: master 2025-10-28 15:33:09,355 zuul.test.FakeGerritConnection DEBUG GET: http://localhost:52721/a/projects/org%2Fcommon-config/HEAD 2025-10-28 15:33:09,355 responses INFO request.allowed-passthru 2025-10-28 15:33:09,355 urllib3.connectionpool DEBUG Resetting dropped connection: localhost 2025-10-28 15:33:09,356 zuul.test.FakeGerritConnection DEBUG Got GET /a/projects/org%2Fcommon-config/HEAD 2025-10-28 15:33:09,356 zuul.test.FakeGerritConnection DEBUG "GET /a/projects/org%2Fcommon-config/HEAD HTTP/1.1" 200 - 2025-10-28 15:33:09,356 urllib3.connectionpool DEBUG http://localhost:52721 "GET /a/projects/org%2Fcommon-config/HEAD HTTP/1.1" 200 24 2025-10-28 15:33:09,357 zuul.GerritConnection.io DEBUG Received: 200 )]}' "refs/heads/master" 2025-10-28 15:33:09,357 zuul.test.FakeGerritConnection INFO Got default branch for org/common-config: master 2025-10-28 15:33:09,375 zuul.MergeClient DEBUG Submitting job b5d53bb6c599416c916fb7518858232c with data {'connection': 'gerrit', 'project': 'org/common-config', 'branch': 'master', 'files': ['zuul.yaml', '.zuul.yaml'], 'dirs': ['zuul.d', '.zuul.d']} 2025-10-28 15:33:09,376 zuul.MergerApi DEBUG Appending merge job to history: b5d53bb6c599416c916fb7518858232c 2025-10-28 15:33:09,376 zuul.MergeClient DEBUG Submitting job fae8c993fb154385bbb067bc3b6b9d68 with data {'connection': 'gerrit', 'project': 'org/project', 'branch': 'master', 'files': ['zuul.yaml', '.zuul.yaml'], 'dirs': ['zuul.d', '.zuul.d']} 2025-10-28 15:33:09,376 zuul.MergerApi DEBUG Appending merge job to history: fae8c993fb154385bbb067bc3b6b9d68 2025-10-28 15:33:09,381 zuul.MergerApi DEBUG Submitting job request to ZooKeeper <MergeRequest b5d53bb6c599416c916fb7518858232c, job_type=cat, state=requested, path=/zuul/merger/requests/b5d53bb6c599416c916fb7518858232c> 2025-10-28 15:33:09,382 zuul.MergerApi DEBUG Submitting job request to ZooKeeper <MergeRequest fae8c993fb154385bbb067bc3b6b9d68, job_type=cat, state=requested, path=/zuul/merger/requests/fae8c993fb154385bbb067bc3b6b9d68> 2025-10-28 15:33:09,396 zuul.TenantParser DEBUG Submitting cat job <JobResultFuture request_path=/zuul/merger/requests/b5d53bb6c599416c916fb7518858232c> for gerrit org/common-config master 2025-10-28 15:33:09,399 zuul.TenantParser DEBUG Submitting cat job <JobResultFuture request_path=/zuul/merger/requests/fae8c993fb154385bbb067bc3b6b9d68> for gerrit org/project master 2025-10-28 15:33:09,399 zuul.TenantParser DEBUG Waiting for cat job <JobResultFuture request_path=/zuul/merger/requests/b5d53bb6c599416c916fb7518858232c> 2025-10-28 15:33:09,418 zuul.JobRequestQueue DEBUG [build: b5d53bb6c599416c916fb7518858232c] Updating request <MergeRequest b5d53bb6c599416c916fb7518858232c, job_type=cat, state=running, path=/zuul/merger/requests/b5d53bb6c599416c916fb7518858232c> 2025-10-28 15:33:09,422 zuul.ExecutorServer DEBUG Next executed merge job: <MergeRequest b5d53bb6c599416c916fb7518858232c, job_type=cat, state=running, path=/zuul/merger/requests/b5d53bb6c599416c916fb7518858232c> 2025-10-28 15:33:09,422 zuul.ExecutorServer DEBUG Got cat job: b5d53bb6c599416c916fb7518858232c 2025-10-28 15:33:09,422 zuul.ExecutorServer INFO Updating repo gerrit/org/common-config 2025-10-28 15:33:09,422 zuul.Repo DEBUG Cloning from file:///tmp/zuul-test/tmpqh2ozn2c/zuul-test/upstream/org/common-config to /tmp/zuul-test/tmpqh2ozn2c/zuul-test/executor-git/review.example.com/org/org%2Fcommon-config 2025-10-28 15:33:09,422 git.util DEBUG sys.platform='linux', git_executable='git' 2025-10-28 15:33:09,435 git.util DEBUG sys.platform='linux', git_executable='git' 2025-10-28 15:33:09,445 git.util DEBUG sys.platform='linux', git_executable='git' 2025-10-28 15:33:09,446 zuul.Merger INFO Updating local repository gerrit/org/common-config 2025-10-28 15:33:09,446 git.util DEBUG sys.platform='linux', git_executable='git' 2025-10-28 15:33:09,446 git.util DEBUG sys.platform='linux', git_executable='git' 2025-10-28 15:33:09,447 zuul.Repo DEBUG Updating repository /tmp/zuul-test/tmpqh2ozn2c/zuul-test/executor-git/review.example.com/org/org%2Fcommon-config 2025-10-28 15:33:09,449 git.util DEBUG sys.platform='linux', git_executable='git' 2025-10-28 15:33:09,449 git.util DEBUG sys.platform='linux', git_executable='git' 2025-10-28 15:33:09,466 zuul.ExecutorServer DEBUG Finished updating repo gerrit/org/common-config 2025-10-28 15:33:09,467 zuul.Repo DEBUG Resetting repository /tmp/zuul-test/tmpqh2ozn2c/zuul-test/executor-git/review.example.com/org/org%2Fcommon-config 2025-10-28 15:33:09,467 git.util DEBUG sys.platform='linux', git_executable='git' 2025-10-28 15:33:09,467 git.util DEBUG sys.platform='linux', git_executable='git' 2025-10-28 15:33:09,469 git.util DEBUG sys.platform='linux', git_executable='git' 2025-10-28 15:33:09,475 git.util DEBUG sys.platform='linux', git_executable='git' 2025-10-28 15:33:09,475 git.util DEBUG sys.platform='linux', git_executable='git' 2025-10-28 15:33:09,489 zuul.Repo DEBUG Getting files for /tmp/zuul-test/tmpqh2ozn2c/zuul-test/executor-git/review.example.com/org/org%2Fcommon-config at 50941099f5696e1fd9bf788581e4a83518f3513a 2025-10-28 15:33:09,494 zuul.ExecutorServer DEBUG Completed cat job b5d53bb6c599416c916fb7518858232c: payload size: 2370 2025-10-28 15:33:09,494 zuul.ExecutorServer INFO Merge <MergeRequest b5d53bb6c599416c916fb7518858232c, job_type=cat, state=running, path=/zuul/merger/requests/b5d53bb6c599416c916fb7518858232c> complete, merged: False, updated: True, commit: None, branches: [] 2025-10-28 15:33:09,494 zuul.ExecutorServer DEBUG Providing synchronous result via future for <MergeRequest b5d53bb6c599416c916fb7518858232c, job_type=cat, state=running, path=/zuul/merger/requests/b5d53bb6c599416c916fb7518858232c> 2025-10-28 15:33:09,503 zuul.JobRequestQueue DEBUG [build: b5d53bb6c599416c916fb7518858232c] Updating request <MergeRequest b5d53bb6c599416c916fb7518858232c, job_type=cat, state=completed, path=/zuul/merger/requests/b5d53bb6c599416c916fb7518858232c> 2025-10-28 15:33:09,507 zuul.test.TestingMergerApi DEBUG Removing request <MergeRequest b5d53bb6c599416c916fb7518858232c, job_type=cat, state=completed, path=/zuul/merger/requests/b5d53bb6c599416c916fb7518858232c> 2025-10-28 15:33:09,515 zuul.TenantParser DEBUG Cat job <JobResultFuture request_path=/zuul/merger/requests/b5d53bb6c599416c916fb7518858232c> got files dict_keys(['.zuul.yaml', 'zuul.yaml']) 2025-10-28 15:33:09,515 zuul.TenantParser INFO Loading configuration from org/common-config/zuul.yaml@master 2025-10-28 15:33:09,534 zuul.JobRequestQueue DEBUG [build: fae8c993fb154385bbb067bc3b6b9d68] Updating request <MergeRequest fae8c993fb154385bbb067bc3b6b9d68, job_type=cat, state=running, path=/zuul/merger/requests/fae8c993fb154385bbb067bc3b6b9d68> 2025-10-28 15:33:09,537 zuul.ExecutorServer DEBUG Next executed merge job: <MergeRequest fae8c993fb154385bbb067bc3b6b9d68, job_type=cat, state=running, path=/zuul/merger/requests/fae8c993fb154385bbb067bc3b6b9d68> 2025-10-28 15:33:09,537 zuul.ExecutorServer DEBUG Got cat job: fae8c993fb154385bbb067bc3b6b9d68 2025-10-28 15:33:09,537 zuul.ExecutorServer INFO Updating repo gerrit/org/project 2025-10-28 15:33:09,538 zuul.Repo DEBUG Cloning from file:///tmp/zuul-test/tmpqh2ozn2c/zuul-test/upstream/org/project to /tmp/zuul-test/tmpqh2ozn2c/zuul-test/executor-git/review.example.com/org/org%2Fproject 2025-10-28 15:33:09,538 git.util DEBUG sys.platform='linux', git_executable='git' 2025-10-28 15:33:09,547 zuul.TenantParser DEBUG Waiting for cat job <JobResultFuture request_path=/zuul/merger/requests/fae8c993fb154385bbb067bc3b6b9d68> 2025-10-28 15:33:09,553 git.util DEBUG sys.platform='linux', git_executable='git' 2025-10-28 15:33:09,560 git.util DEBUG sys.platform='linux', git_executable='git' 2025-10-28 15:33:09,561 zuul.Merger INFO Updating local repository gerrit/org/project 2025-10-28 15:33:09,561 git.util DEBUG sys.platform='linux', git_executable='git' 2025-10-28 15:33:09,562 git.util DEBUG sys.platform='linux', git_executable='git' 2025-10-28 15:33:09,563 zuul.Repo DEBUG Updating repository /tmp/zuul-test/tmpqh2ozn2c/zuul-test/executor-git/review.example.com/org/org%2Fproject 2025-10-28 15:33:09,574 git.util DEBUG sys.platform='linux', git_executable='git' 2025-10-28 15:33:09,574 git.util DEBUG sys.platform='linux', git_executable='git' 2025-10-28 15:33:09,593 zuul.ExecutorServer DEBUG Finished updating repo gerrit/org/project 2025-10-28 15:33:09,593 zuul.Repo DEBUG Resetting repository /tmp/zuul-test/tmpqh2ozn2c/zuul-test/executor-git/review.example.com/org/org%2Fproject 2025-10-28 15:33:09,593 git.util DEBUG sys.platform='linux', git_executable='git' 2025-10-28 15:33:09,594 git.util DEBUG sys.platform='linux', git_executable='git' 2025-10-28 15:33:09,595 git.util DEBUG sys.platform='linux', git_executable='git' 2025-10-28 15:33:09,610 git.util DEBUG sys.platform='linux', git_executable='git' 2025-10-28 15:33:09,611 git.util DEBUG sys.platform='linux', git_executable='git' 2025-10-28 15:33:09,615 zuul.Repo DEBUG Getting files for /tmp/zuul-test/tmpqh2ozn2c/zuul-test/executor-git/review.example.com/org/org%2Fproject at cf12fee35f5ece77bb533eeab80924a3e558b77c 2025-10-28 15:33:09,617 zuul.ExecutorServer DEBUG Completed cat job fae8c993fb154385bbb067bc3b6b9d68: payload size: 153 2025-10-28 15:33:09,617 zuul.ExecutorServer INFO Merge <MergeRequest fae8c993fb154385bbb067bc3b6b9d68, job_type=cat, state=running, path=/zuul/merger/requests/fae8c993fb154385bbb067bc3b6b9d68> complete, merged: False, updated: True, commit: None, branches: [] 2025-10-28 15:33:09,617 zuul.ExecutorServer DEBUG Providing synchronous result via future for <MergeRequest fae8c993fb154385bbb067bc3b6b9d68, job_type=cat, state=running, path=/zuul/merger/requests/fae8c993fb154385bbb067bc3b6b9d68> 2025-10-28 15:33:09,627 zuul.JobRequestQueue DEBUG [build: fae8c993fb154385bbb067bc3b6b9d68] Updating request <MergeRequest fae8c993fb154385bbb067bc3b6b9d68, job_type=cat, state=completed, path=/zuul/merger/requests/fae8c993fb154385bbb067bc3b6b9d68> 2025-10-28 15:33:09,630 zuul.test.TestingMergerApi DEBUG Removing request <MergeRequest fae8c993fb154385bbb067bc3b6b9d68, job_type=cat, state=completed, path=/zuul/merger/requests/fae8c993fb154385bbb067bc3b6b9d68> 2025-10-28 15:33:09,634 zuul.TenantParser DEBUG Cat job <JobResultFuture request_path=/zuul/merger/requests/fae8c993fb154385bbb067bc3b6b9d68> got files dict_keys(['.zuul.yaml', 'zuul.yaml']) 2025-10-28 15:33:09,638 zuul.TenantParser DEBUG Created layout id 52568859162e4f54bab8d9fe3dc095d1 2025-10-28 15:33:09,640 zuul.Pipeline.tenant-one.check DEBUG Building relative_priority queues 2025-10-28 15:33:09,643 zuul.Pipeline.tenant-one.check ERROR Exception loading ZKObject at /zuul/tenant/tenant-one/pipeline/check 2025-10-28 15:33:09,643 zuul.Pipeline.tenant-one.check WARNING Initializing pipeline state for check; this is expected only for new pipelines 2025-10-28 15:33:09,658 zuul.Pipeline.tenant-one.check ERROR Exception loading ZKObject at /zuul/tenant/tenant-one/pipeline/check/change_list 2025-10-28 15:33:09,658 zuul.Pipeline.tenant-one.check WARNING Initializing pipeline change list for check; this is expected only for new pipelines 2025-10-28 15:33:09,664 zuul.Pipeline.tenant-one.gate DEBUG Building shared change queues 2025-10-28 15:33:09,664 zuul.Pipeline.tenant-one.gate DEBUG Created queue: <zuul.manager.shared.ChangeQueueManager object at 0x7f68e0c3e510> 2025-10-28 15:33:09,664 zuul.Pipeline.tenant-one.gate DEBUG Added project org/project to queue managers: <zuul.manager.shared.ChangeQueueManager object at 0x7f68e0c3e510> 2025-10-28 15:33:09,668 zuul.Pipeline.tenant-one.gate ERROR Exception loading ZKObject at /zuul/tenant/tenant-one/pipeline/gate 2025-10-28 15:33:09,668 zuul.Pipeline.tenant-one.gate WARNING Initializing pipeline state for gate; this is expected only for new pipelines 2025-10-28 15:33:09,670 zuul.Pipeline.tenant-one.gate ERROR Exception loading ZKObject at /zuul/tenant/tenant-one/pipeline/gate/change_list 2025-10-28 15:33:09,670 zuul.Pipeline.tenant-one.gate WARNING Initializing pipeline change list for gate; this is expected only for new pipelines 2025-10-28 15:33:09,687 zuul.Pipeline.tenant-one.post DEBUG Building relative_priority queues 2025-10-28 15:33:09,689 zuul.Pipeline.tenant-one.post ERROR Exception loading ZKObject at /zuul/tenant/tenant-one/pipeline/post 2025-10-28 15:33:09,689 zuul.Pipeline.tenant-one.post WARNING Initializing pipeline state for post; this is expected only for new pipelines 2025-10-28 15:33:09,690 zuul.Pipeline.tenant-one.post ERROR Exception loading ZKObject at /zuul/tenant/tenant-one/pipeline/post/change_list 2025-10-28 15:33:09,690 zuul.Pipeline.tenant-one.post WARNING Initializing pipeline change list for post; this is expected only for new pipelines 2025-10-28 15:33:09,695 zuul.Pipeline.tenant-one.tag DEBUG Building relative_priority queues 2025-10-28 15:33:09,696 zuul.Pipeline.tenant-one.tag ERROR Exception loading ZKObject at /zuul/tenant/tenant-one/pipeline/tag 2025-10-28 15:33:09,696 zuul.Pipeline.tenant-one.tag WARNING Initializing pipeline state for tag; this is expected only for new pipelines 2025-10-28 15:33:09,697 zuul.Pipeline.tenant-one.tag ERROR Exception loading ZKObject at /zuul/tenant/tenant-one/pipeline/tag/change_list 2025-10-28 15:33:09,697 zuul.Pipeline.tenant-one.tag WARNING Initializing pipeline change list for tag; this is expected only for new pipelines 2025-10-28 15:33:09,707 zuul.ConfigLoader WARNING 1 errors detected during tenant-one tenant configuration loading 2025-10-28 15:33:09,707 zuul.ConfigLoader WARNING Zuul encountered a deprecated syntax while parsing its configuration in the repo org/common-config on branch master. The problem was: All regular expressions must conform to RE2 syntax, but an expression using the deprecated Perl-style syntax has been detected. Adjust the configuration to conform to RE2 syntax. The RE2 syntax error is: invalid perl operator: (?! The problem appears in the "ref" attribute of the "post" pipeline stanza: ... name: post manager: independent trigger: gerrit: - event: ref-updated ref: ^(?!refs/).$ in "org/common-config/zuul.yaml@master", line 40 2025-10-28 15:33:09,723 zuul.test.FakeGerritConnection DEBUG Setting watched checkers to [] 2025-10-28 15:33:09,723 zuul.test.FakeGerritConnection DEBUG Setting watched event filters for tenant-one to [<GerritEventFilter connection: gerrit types: patchset-created ignore_deletes: True>, <GerritEventFilter connection: gerrit types: comment-added ignore_deletes: True event_approvals: Approved:1>, <GerritEventFilter connection: gerrit types: ref-updated refs: ^(?!refs/).$ ignore_deletes: True>, <GerritEventFilter connection: gerrit types: ref-updated refs: ^refs/tags/.$ ignore_deletes: True>] 2025-10-28 15:33:09,723 zuul.test.FakeGerritConnection DEBUG Setting watched event filters to {<GerritEventFilter connection: gerrit types: ref-updated refs: ^refs/tags/.$ ignore_deletes: True>, <GerritEventFilter connection: gerrit types: patchset-created ignore_deletes: True>, <GerritEventFilter connection: gerrit types: ref-updated refs: ^(?!refs/).$ ignore_deletes: True>, <GerritEventFilter connection: gerrit types: comment-added ignore_deletes: True event_approvals: Approved:1>} 2025-10-28 15:33:09,762 zuul.Scheduler-0 DEBUG Run handler awake 2025-10-28 15:33:09,809 zuul.Scheduler-0 DEBUG Skipping management event queue for tenant tenant-one 2025-10-28 15:33:09,823 zuul.Scheduler-0 DEBUG Skipping locked tenant tenant-one 2025-10-28 15:33:09,825 zuul.Scheduler-0 DEBUG Run handler sleeping 2025-10-28 15:33:09,825 zuul.Scheduler-0 DEBUG Run handler awake 2025-10-28 15:33:09,832 zuul.Scheduler-0 DEBUG Skipping management event queue for tenant tenant-one 2025-10-28 15:33:09,836 zuul.Scheduler-0 DEBUG Skipping locked tenant tenant-one 2025-10-28 15:33:09,837 zuul.Scheduler-0 DEBUG Run handler sleeping 2025-10-28 15:33:09,837 zuul.Scheduler-0 DEBUG Run handler awake 2025-10-28 15:33:09,851 zuul.Scheduler-0 DEBUG Skipping management event queue for tenant tenant-one 2025-10-28 15:33:09,856 zuul.Scheduler-0 DEBUG Skipping locked tenant tenant-one 2025-10-28 15:33:09,858 zuul.Scheduler-0 DEBUG Run handler sleeping 2025-10-28 15:33:09,858 zuul.Scheduler-0 DEBUG Run handler awake 2025-10-28 15:33:09,874 zuul.Scheduler-0 DEBUG Skipping management event queue for tenant tenant-one 2025-10-28 15:33:09,882 zuul.Scheduler-0 DEBUG Skipping locked tenant tenant-one 2025-10-28 15:33:09,892 zuul.Scheduler-0 DEBUG Run handler sleeping 2025-10-28 15:33:09,892 zuul.Scheduler-0 DEBUG Run handler awake 2025-10-28 15:33:09,897 zuul.Scheduler-0 DEBUG Skipping management event queue for tenant tenant-one 2025-10-28 15:33:09,899 zuul.Scheduler-0 DEBUG Skipping locked tenant tenant-one 2025-10-28 15:33:09,901 zuul.Scheduler-0 DEBUG Run handler sleeping 2025-10-28 15:33:09,901 zuul.Scheduler-0 DEBUG Run handler awake 2025-10-28 15:33:09,904 zuul.Scheduler-0 DEBUG Setting layout state last reconfigure ltime to current ltime 1797446 2025-10-28 15:33:09,905 zuul.Scheduler-0 DEBUG Skipping management event queue for tenant tenant-one 2025-10-28 15:33:09,906 zuul.Scheduler-0 DEBUG Skipping locked tenant tenant-one 2025-10-28 15:33:09,907 zuul.Scheduler-0 DEBUG Run handler sleeping 2025-10-28 15:33:09,907 zuul.Scheduler-0 DEBUG Run handler awake 2025-10-28 15:33:09,913 zuul.Scheduler-0 DEBUG Skipping management event queue for tenant tenant-one 2025-10-28 15:33:09,915 zuul.Scheduler-0 DEBUG Skipping locked tenant tenant-one 2025-10-28 15:33:09,916 zuul.Scheduler-0 DEBUG Run handler sleeping 2025-10-28 15:33:09,916 zuul.Scheduler-0 DEBUG Run handler awake 2025-10-28 15:33:09,917 zuul.test.FakeGerritConnection DEBUG Setting watched checkers to [] 2025-10-28 15:33:09,917 zuul.test.FakeGerritConnection DEBUG Setting watched event filters for tenant-one to [<GerritEventFilter connection: gerrit types: patchset-created ignore_deletes: True>, <GerritEventFilter connection: gerrit types: comment-added ignore_deletes: True event_approvals: Approved:1>, <GerritEventFilter connection: gerrit types: ref-updated refs: ^(?!refs/).$ ignore_deletes: True>, <GerritEventFilter connection: gerrit types: ref-updated refs: ^refs/tags/.$ ignore_deletes: True>] 2025-10-28 15:33:09,917 zuul.test.FakeGerritConnection DEBUG Setting watched event filters to {<GerritEventFilter connection: gerrit types: ref-updated refs: ^refs/tags/.$ ignore_deletes: True>, <GerritEventFilter connection: gerrit types: patchset-created ignore_deletes: True>, <GerritEventFilter connection: gerrit types: ref-updated refs: ^(?!refs/).$ ignore_deletes: True>, <GerritEventFilter connection: gerrit types: comment-added ignore_deletes: True event_approvals: Approved:1>} 2025-10-28 15:33:09,917 zuul.Scheduler-0 DEBUG Released tenant-one write tenant lock (id: None) 2025-10-28 15:33:09,919 zuul.Scheduler-0 INFO Config priming complete (duration: 0.83 seconds) 2025-10-28 15:33:09,923 zuul.RendezvousElection DEBUG Election winner for /zuul/events/connection/github/election is None 2025-10-28 15:33:09,923 zuul.RendezvousElection DEBUG Did not win election for /zuul/events/connection/github/election 2025-10-28 15:33:09,923 zuul.RendezvousElection DEBUG Did not win election for /zuul/events/connection/github/election 2025-10-28 15:33:09,924 zuul.RendezvousElection DEBUG Election winner for /zuul/events/connection/gerrit/election is None 2025-10-28 15:33:09,924 zuul.RendezvousElection DEBUG Did not win election for /zuul/events/connection/gerrit/election 2025-10-28 15:33:09,924 zuul.RendezvousElection DEBUG Did not win election for /zuul/events/connection/gerrit/election 2025-10-28 15:33:09,925 zuul.ComponentRegistry DEBUG Registry <zuul.zk.components.ComponentRegistry object at 0x7f6998b31810> got event CHANGED for scheduler np6bc1754cc6fe40000000000 2025-10-28 15:33:09,925 zuul.ComponentRegistry INFO Component scheduler np6bc1754cc6fe40000000000 updated: {'hostname': 'np6bc1754cc6fe4', 'kind': 'scheduler', 'model_api': 36, 'state': 'running', 'version': '13.0.2.dev15 18a7e5884'} 2025-10-28 15:33:09,925 zuul.RendezvousElection DEBUG Election winner for /zuul/events/connection/github/election is <SchedulerComponent {'hostname': 'np6bc1754cc6fe4', 'state': 'running', 'kind': 'scheduler', 'version': '13.0.2.dev15 18a7e5884', 'model_api': 36}> 2025-10-28 15:33:09,925 zuul.RendezvousElection DEBUG Election winner for /zuul/events/connection/gerrit/election is <SchedulerComponent {'hostname': 'np6bc1754cc6fe4', 'state': 'running', 'kind': 'scheduler', 'version': '13.0.2.dev15 18a7e5884', 'model_api': 36}> 2025-10-28 15:33:09,925 zuul.RendezvousElection DEBUG Acquiring lock for /zuul/events/connection/github/election 2025-10-28 15:33:09,926 zuul.RendezvousElection DEBUG Acquiring lock for /zuul/events/connection/gerrit/election 2025-10-28 15:33:09,927 zuul.Launcher DEBUG Updating tenant tenant-one 2025-10-28 15:33:09,927 zuul.Launcher DEBUG Wait for tenant-one read tenant lock 2025-10-28 15:33:09,943 zuul.RendezvousElection INFO Won election for /zuul/events/connection/github/election 2025-10-28 15:33:09,943 zuul.Scheduler-0 DEBUG Processing tenant management events in tenant-one 2025-10-28 15:33:09,944 zuul.Launcher DEBUG Aquired tenant-one read tenant lock 2025-10-28 15:33:09,944 zuul.RendezvousElection INFO Won election for /zuul/events/connection/gerrit/election 2025-10-28 15:33:09,946 zuul.Scheduler.LayoutUpdate DEBUG Aquired tenant-one read tenant lock 2025-10-28 15:33:09,947 zuul.Scheduler.LayoutUpdate DEBUG Released tenant-one read tenant lock 2025-10-28 15:33:09,947 zuul.Scheduler-0 DEBUG Aquired tenant-one read tenant lock 2025-10-28 15:33:09,951 zuul.Launcher DEBUG Loaded provider static-main 2025-10-28 15:33:09,951 zuul.Launcher DEBUG Released tenant-one read tenant lock 2025-10-28 15:33:09,951 zuul.Scheduler-0 DEBUG Processing tenant trigger events in tenant-one 2025-10-28 15:33:09,952 zuul.QuotaCache DEBUG Initialize cache at /zuul/endpoint/static/quota 2025-10-28 15:33:09,962 zuul.QuotaCache DEBUG Cache at /zuul/endpoint/static/quota is ready 2025-10-28 15:33:09,963 zuul.static.static DEBUG Starting static endpoint 2025-10-28 15:33:09,967 zuul.Scheduler-0 DEBUG Processing pipeline check in tenant tenant-one 2025-10-28 15:33:09,969 zuul.Launcher DEBUG Requested node <StaticProviderNode uuid=3e66e3b915185a66acc22d344ca48be2, label=debian-normal, state=building, provider=review.example.com%2Forg%2Fcommon-config/static-main> 2025-10-28 15:33:09,969 zuul.Launcher DEBUG Checking for old images 2025-10-28 15:33:09,969 zuul.Launcher DEBUG Checking for missing images 2025-10-28 15:33:09,969 zuul.Launcher DEBUG Done checking for missing images 2025-10-28 15:33:09,969 zuul.Launcher DEBUG Checking for missing uploads 2025-10-28 15:33:09,970 zuul.zk.ZooKeeper ERROR Exception loading ZKObject at /zuul/nodes/nodes/3e66e3b915185a66acc22d344ca48be2/assignment 2025-10-28 15:33:09,970 zuul.Scheduler-0 ERROR Exception loading ZKObject at /zuul/tenant/tenant-one/pipeline/check/status 2025-10-28 15:33:09,970 zuul.PipelineSummary WARNING No pipeline summary found (may not be created yet) 2025-10-28 15:33:09,971 zuul.Scheduler-0 DEBUG Processing management event <zuul.model.PipelinePostConfigEvent object at 0x7f68dfe4aa90> 2025-10-28 15:33:09,973 zuul.Pipeline.tenant-one.check DEBUG Starting queue processor: check 2025-10-28 15:33:09,973 zuul.Pipeline.tenant-one.check DEBUG Finished queue processor: check (changed: False) 2025-10-28 15:33:09,977 zuul.Scheduler-0 DEBUG Processing pipeline gate in tenant tenant-one 2025-10-28 15:33:09,985 zuul.Scheduler-0 ERROR Exception loading ZKObject at /zuul/tenant/tenant-one/pipeline/gate/status 2025-10-28 15:33:09,985 zuul.PipelineSummary WARNING No pipeline summary found (may not be created yet) 2025-10-28 15:33:09,987 zuul.Scheduler-0 DEBUG Processing management event <zuul.model.PipelinePostConfigEvent object at 0x7f68df159410> 2025-10-28 15:33:09,988 zuul.Pipeline.tenant-one.gate DEBUG Starting queue processor: gate 2025-10-28 15:33:09,988 zuul.Pipeline.tenant-one.gate DEBUG Finished queue processor: gate (changed: False) 2025-10-28 15:33:09,994 zuul.Scheduler-0 DEBUG Processing pipeline post in tenant tenant-one 2025-10-28 15:33:09,995 zuul.Scheduler-0 DEBUG Starting semaphore cleanup 2025-10-28 15:33:10,005 zuul.Scheduler-0 ERROR Exception loading ZKObject at /zuul/tenant/tenant-one/pipeline/post/status 2025-10-28 15:33:10,005 zuul.PipelineSummary WARNING No pipeline summary found (may not be created yet) 2025-10-28 15:33:10,006 zuul.Scheduler-0 DEBUG Starting build request cleanup 2025-10-28 15:33:10,006 zuul.Scheduler-0 DEBUG Finished build request cleanup 2025-10-28 15:33:10,007 zuul.Scheduler-0 DEBUG Processing management event <zuul.model.PipelinePostConfigEvent object at 0x7f68e6b09390> 2025-10-28 15:33:10,008 zuul.Scheduler-0 DEBUG Starting node request cleanup 2025-10-28 15:33:10,009 zuul.Pipeline.tenant-one.post DEBUG Starting queue processor: post 2025-10-28 15:33:10,009 zuul.Pipeline.tenant-one.post DEBUG Finished queue processor: post (changed: False) 2025-10-28 15:33:10,023 zuul.Launcher ERROR Exception loading ZKObject at /zuul/nodes/nodes/3e66e3b915185a66acc22d344ca48be2/assignment 2025-10-28 15:33:10,023 zuul.Launcher DEBUG Building node <StaticProviderNode uuid=3e66e3b915185a66acc22d344ca48be2, label=debian-normal, state=building, provider=review.example.com%2Forg%2Fcommon-config/static-main> 2025-10-28 15:33:10,023 zuul.Launcher DEBUG Node <StaticProviderNode uuid=3e66e3b915185a66acc22d344ca48be2, label=debian-normal, state=building, provider=review.example.com%2Forg%2Fcommon-config/static-main> external id None 2025-10-28 15:33:10,023 zuul.Launcher DEBUG Submitted nodescan request for 198.51.100.1 queue length 1 2025-10-28 15:33:10,024 zuul.Scheduler-0 DEBUG Processing pipeline tag in tenant tenant-one 2025-10-28 15:33:10,027 zuul.Scheduler-0 ERROR Exception loading ZKObject at /zuul/tenant/tenant-one/pipeline/tag/status 2025-10-28 15:33:10,027 zuul.PipelineSummary WARNING No pipeline summary found (may not be created yet) 2025-10-28 15:33:10,031 zuul.Scheduler-0 DEBUG Processing management event <zuul.model.PipelinePostConfigEvent object at 0x7f69917ea390> 2025-10-28 15:33:10,037 zuul.Pipeline.tenant-one.tag DEBUG Starting queue processor: tag 2025-10-28 15:33:10,038 zuul.Pipeline.tenant-one.tag DEBUG Finished queue processor: tag (changed: False) 2025-10-28 15:33:10,047 zuul.Scheduler-0 DEBUG Released tenant-one read tenant lock 2025-10-28 15:33:10,048 zuul.Scheduler-0 DEBUG Run handler sleeping 2025-10-28 15:33:10,048 zuul.Scheduler-0 DEBUG Run handler awake 2025-10-28 15:33:10,058 apscheduler.scheduler INFO Added job "TestScheduler._runSemaphoreCleanup" to job store "default" 2025-10-28 15:33:10,058 apscheduler.scheduler INFO Added job "TestScheduler._runBuildRequestCleanup" to job store "default" 2025-10-28 15:33:10,058 apscheduler.scheduler INFO Added job "TestScheduler._runMergeRequestCleanup" to job store "default" 2025-10-28 15:33:10,058 apscheduler.scheduler INFO Added job "TestScheduler._runConnectionCleanup" to job store "default" 2025-10-28 15:33:10,058 apscheduler.scheduler INFO Added job "TestScheduler._runGeneralCleanup" to job store "default" 2025-10-28 15:33:10,058 apscheduler.scheduler DEBUG Looking for jobs to run 2025-10-28 15:33:10,059 apscheduler.scheduler DEBUG Next wakeup is due at 2025-10-28 15:33:51.230777+00:00 (in 41.171757 seconds) 2025-10-28 15:33:10,060 zuul.Scheduler-0 DEBUG Processing tenant management events in tenant-one 2025-10-28 15:33:10,064 zuul.Scheduler-0 DEBUG Aquired tenant-one read tenant lock 2025-10-28 15:33:10,071 zuul.Scheduler-0 DEBUG Processing tenant trigger events in tenant-one 2025-10-28 15:33:10,085 zuul.Launcher DEBUG Added ssh host key: fake key 2025-10-28 15:33:10,085 zuul.Launcher DEBUG Nodescan request complete with 1 keys, 1 initial connection attempts, 0 key connection failures, 0 key negotiation failures in 0 seconds 2025-10-28 15:33:10,121 zuul.Launcher DEBUG Marking node <StaticProviderNode uuid=3e66e3b915185a66acc22d344ca48be2, label=debian-normal, state=ready, provider=review.example.com%2Forg%2Fcommon-config/static-main> as ready 2025-10-28 15:33:10,126 zuul.test ERROR Exception loading ZKObject at /zuul/nodes/nodes/3e66e3b915185a66acc22d344ca48be2/assignment 2025-10-28 15:33:10,132 zuul.Scheduler-0 DEBUG Processing pipeline check in tenant tenant-one 2025-10-28 15:33:10,136 zuul.Scheduler-0 DEBUG No events to process for pipeline check in tenant tenant-one 2025-10-28 15:33:10,137 opentelemetry.attributes WARNING Invalid type NoneType for attribute 'request_uuid' value. Expected one of ['bool', 'str', 'bytes', 'int', 'float'] or a sequence of those types 2025-10-28 15:33:10,137 opentelemetry.attributes WARNING Invalid type NoneType for attribute 'zuul_event_id' value. Expected one of ['bool', 'str', 'bytes', 'int', 'float'] or a sequence of those types 2025-10-28 15:33:10,141 zuul.test ERROR Exception saving ZKObject <StaticProviderNode uuid=3e66e3b915185a66acc22d344ca48be2, label=debian-normal, state=used, provider=review.example.com%2Forg%2Fcommon-config/static-main> at /zuul/nodes/nodes/3e66e3b915185a66acc22d344ca48be2 2025-10-28 15:33:10,144 zuul.Scheduler-0 DEBUG Processing pipeline gate in tenant tenant-one 2025-10-28 15:33:10,146 zuul.test DEBUG Assert final state 2025-10-28 15:33:10,781 zuul.Launcher DEBUG Provider endpoint quota limits for static-main: {} 2025-10-28 15:33:10,808 zuul.Scheduler-0 DEBUG No events to process for pipeline gate in tenant tenant-one 2025-10-28 15:33:10,821 zuul.test DEBUG Leaked git repo object: 0x7f69962ac910 <git.repo.base.Repo '/tmp/zuul-test/tmpta4l5rkt/zuul-test/upstream/gh/project/.git'> 2025-10-28 15:33:10,821 zuul.test DEBUG Leaked git repo object: 0x7f693053d550 <git.repo.base.Repo '/tmp/zuul-test/tmpta4l5rkt/zuul-test/upstream/gh/project1/.git'> 2025-10-28 15:33:10,821 zuul.test DEBUG Leaked git repo object: 0x7f6990149650 <git.repo.base.Repo '/tmp/zuul-test/tmpta4l5rkt/zuul-test/upstream/gh/project1/.git'> 2025-10-28 15:33:10,821 zuul.test DEBUG Leaked git repo object: 0x7f6995fd5550 <git.repo.base.Repo '/tmp/zuul-test/tmpta4l5rkt/zuul-test/upstream/gh/project1/.git'> 2025-10-28 15:33:10,821 zuul.test DEBUG Leaked git repo object: 0x7f6990800ad0 <git.repo.base.Repo '/tmp/zuul-test/tmpta4l5rkt/zuul-test/upstream/gh/project1/.git'> 2025-10-28 15:33:10,838 zuul.test DEBUG Leaked git repo object: 0x7f6973f91ad0 <git.repo.base.Repo '/tmp/zuul-test/tmp9trmo7ep/zuul-test/upstream/org/project/.git'> 2025-10-28 15:33:10,841 zuul.test DEBUG Leaked git repo object: 0x7f6997d59e50 <git.repo.base.Repo '/tmp/zuul-test/tmpo3z8xhax/zuul-test/upstream/org/project5/.git'> 2025-10-28 15:33:10,921 zuul.test DEBUG Leaked git repo object: 0x7f68e3e480d0 <git.repo.base.Repo '/tmp/zuul-test/tmpn62y_4qp/zuul-test/upstream/org/project/.git'> 2025-10-28 15:33:10,940 zuul.Launcher DEBUG [req: dne] Deallocating node <StaticProviderNode uuid=3e66e3b915185a66acc22d344ca48be2, label=debian-normal, state=ready, provider=review.example.com%2Forg%2Fcommon-config/static-main> from missing request dne 2025-10-28 15:33:10,945 zuul.Scheduler-0 DEBUG Processing pipeline post in tenant tenant-one 2025-10-28 15:33:10,951 zuul.Scheduler-0 DEBUG No events to process for pipeline post in tenant tenant-one 2025-10-28 15:33:10,958 zuul.Scheduler-0 DEBUG Processing pipeline tag in tenant tenant-one 2025-10-28 15:33:10,968 zuul.test DEBUG Shutting down after tests 2025-10-28 15:33:10,968 zuul.ExecutorServer DEBUG No running builds to release 2025-10-28 15:33:10,968 zuul.ExecutorClient DEBUG Stopping 2025-10-28 15:33:10,968 zuul.ExecutorServer DEBUG Stopping executor 2025-10-28 15:33:10,971 zuul.test.FakeGerritConnection DEBUG Stopping Gerrit Connection/Watchers 2025-10-28 15:33:10,971 zuul.ComponentRegistry DEBUG Registry <zuul.zk.components.ComponentRegistry object at 0x7f6998b31810> got event CHANGED for executor np6bc1754cc6fe40000000000 2025-10-28 15:33:10,971 zuul.ComponentRegistry INFO Component executor np6bc1754cc6fe40000000000 updated: {'accepting_work': True, 'allow_unzoned': True, 'hostname': 'np6bc1754cc6fe4', 'kind': 'executor', 'model_api': 36, 'process_merge_jobs': True, 'state': 'stopped', 'version': '13.0.2.dev15 18a7e5884', 'zone': None} 2025-10-28 15:33:10,971 zuul.RendezvousElection DEBUG Election winner for /zuul/events/connection/github/election is <SchedulerComponent {'hostname': 'np6bc1754cc6fe4', 'state': 'running', 'kind': 'scheduler', 'version': '13.0.2.dev15 18a7e5884', 'model_api': 36}> 2025-10-28 15:33:10,971 zuul.RendezvousElection DEBUG Election winner for /zuul/events/connection/gerrit/election is <SchedulerComponent {'hostname': 'np6bc1754cc6fe4', 'state': 'running', 'kind': 'scheduler', 'version': '13.0.2.dev15 18a7e5884', 'model_api': 36}> 2025-10-28 15:33:10,972 zuul.Scheduler-0 DEBUG No events to process for pipeline tag in tenant tenant-one 2025-10-28 15:33:10,973 zuul.Scheduler-0 DEBUG Released tenant-one read tenant lock 2025-10-28 15:33:10,974 zuul.Scheduler-0 DEBUG Run handler sleeping 2025-10-28 15:33:11,192 zuul.TimerDriver DEBUG Stopping timer driver 2025-10-28 15:33:11,192 zuul.TimerDriver DEBUG Stopping apscheduler 2025-10-28 15:33:11,192 apscheduler.scheduler INFO Scheduler has been shut down 2025-10-28 15:33:11,193 apscheduler.scheduler DEBUG Looking for jobs to run 2025-10-28 15:33:11,193 apscheduler.scheduler DEBUG No jobs; waiting until a job is added 2025-10-28 15:33:11,193 zuul.TimerDriver DEBUG Stopped apscheduler 2025-10-28 15:33:11,193 zuul.TimerDriver DEBUG Stopped timer driver 2025-10-28 15:33:11,193 zuul.CommandSocket DEBUG Accepted socket connection <socket.socket fd=39, family=1, type=1, proto=0, laddr=/tmp/zuul-test/tmpqh2ozn2c/zuul-test/executor.socket> 2025-10-28 15:33:11,194 zuul.CommandSocket DEBUG Received b'_stop' from socket 2025-10-28 15:33:11,195 zuul.ExecutorServer DEBUG Stopping base merge server 2025-10-28 15:33:11,195 zuul.ExecutorServer DEBUG Stopped base merge server 2025-10-28 15:33:11,195 zuul.ExecutorServer DEBUG Stopped executor 2025-10-28 15:33:11,195 zuul.ExecutorServer DEBUG Joining executor 2025-10-28 15:33:11,195 zuul.ExecutorServer DEBUG Joining base merge server 2025-10-28 15:33:11,199 zuul.zk.base.ZooKeeperClient DEBUG ZooKeeper connection (session: 0x0): LOST 2025-10-28 15:33:11,199 zuul.ExecutorServer DEBUG Joined base merge server 2025-10-28 15:33:11,199 zuul.ExecutorServer DEBUG Joined executor 2025-10-28 15:33:11,199 zuul.Launcher DEBUG Stopping launcher 2025-10-28 15:33:11,202 zuul.CommandSocket DEBUG Accepted socket connection <socket.socket fd=74, family=1, type=1, proto=0, laddr=/tmp/zuul-test/tmpqh2ozn2c/zuul-test/launcher-0.socket> 2025-10-28 15:33:11,202 zuul.CommandSocket DEBUG Received b'_stop' from socket 2025-10-28 15:33:11,202 zuul.Launcher DEBUG Stopping stats thread 2025-10-28 15:33:11,202 zuul.Launcher DEBUG Stopping cleanup worker 2025-10-28 15:33:11,202 zuul.Launcher DEBUG Joining cleanup thread 2025-10-28 15:33:11,202 zuul.Launcher DEBUG Joined cleanup thread 2025-10-28 15:33:11,202 zuul.TimerDriver DEBUG Stopping timer driver 2025-10-28 15:33:11,202 zuul.TimerDriver DEBUG Stopping apscheduler 2025-10-28 15:33:11,202 apscheduler.scheduler INFO Scheduler has been shut down 2025-10-28 15:33:11,202 apscheduler.scheduler DEBUG Looking for jobs to run 2025-10-28 15:33:11,202 apscheduler.scheduler DEBUG No jobs; waiting until a job is added 2025-10-28 15:33:11,203 zuul.TimerDriver DEBUG Stopped apscheduler 2025-10-28 15:33:11,203 zuul.TimerDriver DEBUG Stopped timer driver 2025-10-28 15:33:11,203 zuul.static.static DEBUG Stopping static endpoint 2025-10-28 15:33:11,203 zuul.Launcher DEBUG Stopped launcher 2025-10-28 15:33:11,203 zuul.Launcher DEBUG Joining launcher 2025-10-28 15:33:11,203 zuul.zk.base.ZooKeeperClient DEBUG ZooKeeper connection (session: 0x0): LOST 2025-10-28 15:33:11,204 zuul.Launcher DEBUG Joined launcher 2025-10-28 15:33:11,204 zuul.Scheduler-0 DEBUG Stopping scheduler 2025-10-28 15:33:11,204 zuul.Scheduler-0 DEBUG Stopping apscheduler 2025-10-28 15:33:11,204 apscheduler.scheduler INFO Scheduler has been shut down 2025-10-28 15:33:11,204 apscheduler.scheduler DEBUG Looking for jobs to run 2025-10-28 15:33:11,204 apscheduler.scheduler DEBUG No jobs; waiting until a job is added 2025-10-28 15:33:11,204 zuul.Scheduler-0 DEBUG Run handler stopping 2025-10-28 15:33:11,204 zuul.Scheduler-0 DEBUG Waiting for main thread 2025-10-28 15:33:11,205 zuul.Scheduler-0 DEBUG Stopping nodepool 2025-10-28 15:33:11,205 zuul.nodepool DEBUG Stopping 2025-10-28 15:33:11,205 zuul.Scheduler-0 DEBUG Stopping connections 2025-10-28 15:33:11,206 zuul.Scheduler-0 DEBUG Waiting for layout update thread 2025-10-28 15:33:11,206 zuul.SQLConnection DEBUG Stopping SQL connection database 2025-10-28 15:33:11,206 zuul.test.FakeGerritConnection DEBUG Stopping Gerrit Connection/Watchers 2025-10-28 15:33:11,206 zuul.GerritConnection.poller DEBUG Stopping watcher 2025-10-28 15:33:11,207 zuul.RendezvousElection INFO Finished term for /zuul/events/connection/gerrit/election 2025-10-28 15:33:11,683 zuul.RendezvousElection INFO Finished term for /zuul/events/connection/github/election 2025-10-28 15:33:11,684 zuul.TimerDriver DEBUG Stopping timer driver 2025-10-28 15:33:11,684 zuul.TimerDriver DEBUG Stopping apscheduler 2025-10-28 15:33:11,684 apscheduler.scheduler INFO Scheduler has been shut down 2025-10-28 15:33:11,684 zuul.TimerDriver DEBUG Timer election tenure ended 2025-10-28 15:33:11,684 apscheduler.scheduler DEBUG Looking for jobs to run 2025-10-28 15:33:11,684 apscheduler.scheduler DEBUG No jobs; waiting until a job is added 2025-10-28 15:33:11,684 zuul.TimerDriver DEBUG Stopped apscheduler 2025-10-28 15:33:11,684 zuul.TimerDriver DEBUG Stopping election 2025-10-28 15:33:11,684 zuul.TimerDriver DEBUG Stopped election 2025-10-28 15:33:11,684 zuul.TimerDriver DEBUG Stopping election thread 2025-10-28 15:33:11,684 zuul.TimerDriver DEBUG Exiting timer election loop 2025-10-28 15:33:11,684 zuul.TimerDriver DEBUG Stopped election thread 2025-10-28 15:33:11,684 zuul.TimerDriver DEBUG Stopped timer driver 2025-10-28 15:33:11,684 zuul.Scheduler-0 DEBUG Stopping stats thread 2025-10-28 15:33:11,684 zuul.Scheduler-0 DEBUG Stopping command socket 2025-10-28 15:33:11,685 zuul.CommandSocket DEBUG Accepted socket connection <socket.socket fd=7, family=1, type=1, proto=0, laddr=/tmp/zuul-test/tmpqh2ozn2c/zuul-test/scheduler-0.socket> 2025-10-28 15:33:11,685 zuul.CommandSocket DEBUG Received b'_stop' from socket 2025-10-28 15:33:11,685 zuul.Scheduler-0 DEBUG Stopping timedb thread 2025-10-28 15:33:11,685 zuul.Scheduler-0 DEBUG Stopping monitoring server 2025-10-28 15:33:11,685 zuul.Scheduler-0 DEBUG Disconnecting from ZooKeeper 2025-10-28 15:33:11,686 zuul.zk.base.ZooKeeperClient DEBUG ZooKeeper connection (session: 0x0): LOST 2025-10-28 15:33:11,686 zuul.Scheduler-0 DEBUG Stopping tracing 2025-10-28 15:33:11,686 zuul.ExecutorClient DEBUG Stopping 2025-10-28 15:33:11,758 zuul.zk.base.ZooKeeperClient DEBUG ZooKeeper connection (session: 0x0): LOST 2025-10-28 15:33:11,758 zuul.test DEBUG Build history: no builds ran 2025-10-28 15:33:11,758 zuul.test.MySQLSchemaFixture DEBUG Deleting database 127.0.0.1:3306:DWJwsoyk_8564 }}} Traceback (most recent call last): File "/home/zuul/src/opendev.org/zuul/zuul/tests/unit/test_static_driver.py", line 403, in test_static_deregistration_in_use with main.activeContext(ctx): File "/usr/lib/python3.11/contextlib.py", line 144, in __exit__ next(self.gen) File "/home/zuul/src/opendev.org/zuul/zuul/zuul/zk/zkobject.py", line 236, in activeContext self._save(context, serial) File "/home/zuul/src/opendev.org/zuul/zuul/zuul/zk/zkobject.py", line 481, in _save zstat = self._retry(context, self._retryableSave, ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/home/zuul/src/opendev.org/zuul/zuul/zuul/zk/zkobject.py", line 370, in _retry return kazoo_retry(func, args, *kw) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/home/zuul/src/opendev.org/zuul/zuul/.nox/tests-3-11/lib/python3.11/site-packages/kazoo/retry.py", line 126, in __call__ return func(args, **kwargs) ^^^^^^^^^^^^^^^^^^^^^ File "/home/zuul/src/opendev.org/zuul/zuul/zuul/zk/zkobject.py", line 453, in _retryableSave stream.write(data) File "/home/zuul/src/opendev.org/zuul/zuul/zuul/zk/sharding.py", line 78, in write self.zstat = self.client.set(self.path, data, ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/home/zuul/src/opendev.org/zuul/zuul/.nox/tests-3-11/lib/python3.11/site-packages/kazoo/client.py", line 1359, in set return self.set_async(path, value, version).get() ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/home/zuul/src/opendev.org/zuul/zuul/.nox/tests-3-11/lib/python3.11/site-packages/kazoo/handlers/utils.py", line 86, in get raise self._exception kazoo.exceptions.BadVersionError
test_static_node_aliases	pass [x] pt1.7: tests.unit.test_static_driver.TestStaticDriver.test_static_node_aliases
test_static_subnodes_deregistration_in_use	pass [x] pt1.8: tests.unit.test_static_driver.TestStaticDriver.test_static_subnodes_deregistration_in_use
test_static_subnodes_failure	pass [x] pt1.9: tests.unit.test_static_driver.TestStaticDriver.test_static_subnodes_failure
test_static_subnodes_reuse_failure	pass [x] pt1.10: tests.unit.test_static_driver.TestStaticDriver.test_static_subnodes_reuse_failure
tests.unit.test_auth.TestOpenIDConnectAuthenticator	1	1	0	0	0	Detail
test_decodeToken	pass [x] pt2.1: tests.unit.test_auth.TestOpenIDConnectAuthenticator.test_decodeToken
tests.unit.test_aws_driver.TestAwsDriver	20	20	0	0	0	Detail
test_aws_diskimage_image_import	pass [x] pt3.1: tests.unit.test_aws_driver.TestAwsDriver.test_aws_diskimage_image_import
test_aws_diskimage_copy	pass [x] pt3.2: tests.unit.test_aws_driver.TestAwsDriver.test_aws_diskimage_copy
test_aws_diskimage_ebs_direct	pass [x] pt3.3: tests.unit.test_aws_driver.TestAwsDriver.test_aws_diskimage_ebs_direct
test_aws_diskimage_s3_region_download	pass [x] pt3.4: tests.unit.test_aws_driver.TestAwsDriver.test_aws_diskimage_s3_region_download
test_aws_diskimage_image	pass [x] pt3.5: tests.unit.test_aws_driver.TestAwsDriver.test_aws_diskimage_image
test_aws_diskimage_snapshot	pass [x] pt3.6: tests.unit.test_aws_driver.TestAwsDriver.test_aws_diskimage_snapshot
test_aws_multi_image	pass [x] pt3.7: tests.unit.test_aws_driver.TestAwsDriver.test_aws_multi_image
test_aws_diskimage_s3_download	pass [x] pt3.8: tests.unit.test_aws_driver.TestAwsDriver.test_aws_diskimage_s3_download
test_aws_diskimage_snapshot_import	pass [x] pt3.9: tests.unit.test_aws_driver.TestAwsDriver.test_aws_diskimage_snapshot_import
test_aws_resource_cleanup_import_image	pass [x] pt3.10: tests.unit.test_aws_driver.TestAwsDriver.test_aws_resource_cleanup_import_image
test_aws_node_lifecycle	pass [x] pt3.11: tests.unit.test_aws_driver.TestAwsDriver.test_aws_node_lifecycle
test_aws_node_lifecycle_fleet	pass [x] pt3.12: tests.unit.test_aws_driver.TestAwsDriver.test_aws_node_lifecycle_fleet
test_aws_node_lifecycle_spot	pass [x] pt3.13: tests.unit.test_aws_driver.TestAwsDriver.test_aws_node_lifecycle_spot
test_aws_resource_limits	pass [x] pt3.14: tests.unit.test_aws_driver.TestAwsDriver.test_aws_resource_limits
test_state_machines_dedicated_host	pass [x] pt3.15: tests.unit.test_aws_driver.TestAwsDriver.test_state_machines_dedicated_host
test_aws_quota	pass [x] pt3.16: tests.unit.test_aws_driver.TestAwsDriver.test_aws_quota
test_state_machines_instance	pass [x] pt3.17: tests.unit.test_aws_driver.TestAwsDriver.test_state_machines_instance
test_aws_resource_cleanup	pass [x] pt3.18: tests.unit.test_aws_driver.TestAwsDriver.test_aws_resource_cleanup
test_aws_resource_cleanup_import_snapshot	pass [x] pt3.19: tests.unit.test_aws_driver.TestAwsDriver.test_aws_resource_cleanup_import_snapshot
test_snapshot_leak	pass [x] pt3.20: tests.unit.test_aws_driver.TestAwsDriver.test_snapshot_leak
tests.unit.test_aws_driver.TestAwsSnapshot	1	1	0	0	0	Detail
test_snapshot_e2e	pass [x] pt4.1: tests.unit.test_aws_driver.TestAwsSnapshot.test_snapshot_e2e
tests.unit.test_bubblewrap.TestBubblewrap	2	2	0	0	0	Detail
test_bubblewrap_wraps	pass [x] pt5.1: tests.unit.test_bubblewrap.TestBubblewrap.test_bubblewrap_wraps
test_bubblewrap_leak	pass [x] pt5.2: tests.unit.test_bubblewrap.TestBubblewrap.test_bubblewrap_leak