| ===================================================================================== test session starts ======================================================================================
|
| platform linux -- Python 3.11.6, pytest-8.3.3, pluggy-1.5.0 -- /home/jdietz/.pyenv/versions/myenv11/bin/python3.11
|
| rootdir: /home/jdietz/workspace/mdt-automation2
|
| configfile: pytest.ini
|
| plugins: alsi-3.1.4, mdt-2.1.3.dev18+gba22e98.d20241118
|
| collecting ...
|
| collected 1 item
|
|
|
| tests/mdtagent/test_envelope.py::test_large_bundle_envelope_processing
|
| ---------------------------------------------------------------------------------------- live log setup ----------------------------------------------------------------------------------------
|
| 2025-01-06 13:21:52 [32mINFO [0m python_alsi.testnet.networks:272 - Loading networks from testnet sqa2.
|
| 2025-01-06 13:21:52 [35mDEBUG [0m python_alsi.util.__call__:474 - Creating a new instance of DirectNetwork for key testnet=<python_alsi.testnet.DirectTestnet object at 0x7f4a9e8c35d0>,name=freeflow,fetcher=<python_alsi.perforce.PathFetcher object at 0x7f4a9f256b10>
|
| 2025-01-06 13:21:53 [35mDEBUG [0m python_alsi.util.__call__:474 - Creating a new instance of DirectNetwork for key testnet=<python_alsi.testnet.DirectTestnet object at 0x7f4a9e8c35d0>,name=infra,fetcher=<python_alsi.perforce.PathFetcher object at 0x7f4a9f256b10>
|
| 2025-01-06 13:21:53 [35mDEBUG [0m python_alsi.util.__call__:474 - Creating a new instance of DirectNetwork for key testnet=<python_alsi.testnet.DirectTestnet object at 0x7f4a9e8c35d0>,name=ff,fetcher=<python_alsi.perforce.PathFetcher object at 0x7f4a9f256b10>
|
| 2025-01-06 13:21:54 [35mDEBUG [0m python_alsi.util.__call__:474 - Creating a new instance of DirectNetwork for key testnet=<python_alsi.testnet.DirectTestnet object at 0x7f4a9e8c35d0>,name=ness,fetcher=<python_alsi.perforce.PathFetcher object at 0x7f4a9f256b10>
|
| 2025-01-06 13:21:54 [35mDEBUG [0m python_alsi.util.__call__:474 - Creating a new instance of DirectNetwork for key testnet=<python_alsi.testnet.DirectTestnet object at 0x7f4a9e8c35d0>,name=essl,fetcher=<python_alsi.perforce.PathFetcher object at 0x7f4a9f256b10>
|
| 2025-01-06 13:21:54 [35mDEBUG [0m python_alsi.util.__call__:474 - Creating a new instance of DirectNetwork for key testnet=<python_alsi.testnet.DirectTestnet object at 0x7f4a9e8c35d0>,name=volta,fetcher=<python_alsi.perforce.PathFetcher object at 0x7f4a9f256b10>
|
| 2025-01-06 13:21:55 [35mDEBUG [0m python_alsi.util.__call__:474 - Creating a new instance of DirectNetwork for key testnet=<python_alsi.testnet.DirectTestnet object at 0x7f4a9e8c35d0>,name=metanet,fetcher=<python_alsi.perforce.PathFetcher object at 0x7f4a9f256b10>
|
| 2025-01-06 13:21:55 [32mINFO [0m python_alsi.testnet.networks:277 - Loaded 7 networks from testnet sqa2.
|
| 2025-01-06 13:21:55 [35mDEBUG [0m python_alsi.network.determine_machine_ips:106 - Found machine IP(s): 198.18.81.48
|
| 2025-01-06 13:21:55 [35mDEBUG [0m python_alsi.util.__call__:474 - Creating a new instance of Machine for key network=<python_alsi.network.DirectNetwork object at 0x7f4a9dc5dd50>,ip=198.18.81.48
|
| 2025-01-06 13:21:55 [35mDEBUG [0m python_alsi.util.__call__:474 - Creating a new instance of ConnManager for key ip=198.18.81.48,nat_gateway=None,authgate=None
|
| 2025-01-06 13:21:55 [32mINFO [0m python_alsi.query.__init__:84 - Query agg host: agg-metanet.sqa2.qa.akamai.com (198.18.81.48)
|
| 2025-01-06 13:21:55 [35mDEBUG [0m python_alsi.query._refresh_query:201 - Running query on agg-metanet.sqa2.qa.akamai.com: select distinct system from mdt_systems;
|
| 2025-01-06 13:21:55 [32mINFO [0m python_alsi.connection.connection:168 - [198.18.81.48] Connecting as user root
|
| 2025-01-06 13:21:55 [35mDEBUG [0m python_alsi.connection.connection:193 - [198.18.81.48] Connecting directly using ssh
|
| 2025-01-06 13:21:55 [35mDEBUG [0m python_alsi.connection.initialize_pipe:665 - Connection command: ['ssh', '-e', 'none', '-A', '-oControlMaster=auto', '-oControlPersist=10m', '-oControlPath=/home/jdietz/.ssh/controlmasters/None-%r@%h:%p', '-oStrictHostKeyChecking=no', '-oBatchMode=yes', '-l', 'root', '198.18.81.48']
|
| 2025-01-06 13:21:55 [35mDEBUG [0m python_alsi.connection.initialize_pipe:669 - Established contact with 198.18.81.48
|
| 2025-01-06 13:21:56 [35mDEBUG [0m python_alsi.connection._setup_rpyc:485 - Waiting for remote shell.
|
| 2025-01-06 13:21:56 [35mDEBUG [0m python_alsi.connection._setup_rpyc:492 - Starting up rpyc on the remote machine (Python: /usr/local/akamai/bin/python3.11).
|
| 2025-01-06 13:21:56 [35mDEBUG [0m python_alsi.connection.__init__:685 - Connecting to remote rpyc server with: ['ssh', '-e', 'none', '-A', '-oControlMaster=auto', '-oControlPersist=10m', '-oControlPath=/home/jdietz/.ssh/controlmasters/None-%r@%h:%p', '-oStrictHostKeyChecking=no', '-oBatchMode=yes', '-l', 'root', '198.18.81.48', 'sh', '-c', '"echo SYNC0;exec sh"']
|
| 2025-01-06 13:21:57 [35mDEBUG [0m python_alsi.connection.__init__:696 - Connected.
|
| 2025-01-06 13:21:59 [35mDEBUG [0m python_alsi.query._run_query:263 - Command took 1 seconds
|
| 2025-01-06 13:21:59 [35mDEBUG [0m python_alsi.query._handle_result:321 - Caching result.
|
| 2025-01-06 13:21:59 [35mDEBUG [0m root.mdt_system_fixture:66 - Available MDT systems: ['mdt-test-auto', 'freeflow']; using mdt-test-auto
|
| 2025-01-06 13:21:59 [35mDEBUG [0m root.mdtserver_machines_fixture:111 - Initializing mdtserver_machines fixture
|
| 2025-01-06 13:21:59 [32mINFO [0m python_mdt.machine.mdtservermachine.get_mdtserver_machine_ips:117 - Determining MDT server machine instances for MDT system 'mdt-test-auto' in testnet 'sqa2'
|
| 2025-01-06 13:21:59 [35mDEBUG [0m python_alsi.query._refresh_query:201 - Running query on agg-metanet.sqa2.qa.akamai.com: select mdt_systems.machineip ip from mdt_systems left outer join serviceinfo on mdt_systems.machineip=serviceinfo.machineip where serviceinfo.service='mdtreceiver' and serviceinfo.status='up' and mdt_systems.system='mdt-test-auto';
|
| 2025-01-06 13:22:01 [35mDEBUG [0m python_alsi.query._run_query:263 - Command took 1 seconds
|
| 2025-01-06 13:22:01 [35mDEBUG [0m python_alsi.query._handle_result:321 - Caching result.
|
| 2025-01-06 13:22:01 [32mINFO [0m python_mdt.machine.mdtservermachine.get_mdtserver_machine_ips:128 - Found 3 MDT server machine(s) for MDT system 'mdt-test-auto' in testnet 'sqa2'
|
| 2025-01-06 13:22:01 [35mDEBUG [0m python_alsi.util.__call__:474 - Creating a new instance of MdtServerMachine for key network=<python_alsi.network.DirectNetwork object at 0x7f4a9dc94750>,ip=198.19.8.4
|
| 2025-01-06 13:22:01 [35mDEBUG [0m python_alsi.util.__call__:474 - Creating a new instance of ConnManager for key ip=198.19.8.4,nat_gateway=None,authgate=None
|
| 2025-01-06 13:22:01 [35mDEBUG [0m python_alsi.machine.run_cmd:249 - [198.19.8.4] Running 'ls /a/ssl-rotation-manager/conf/*.json' as root
|
| 2025-01-06 13:22:01 [32mINFO [0m python_alsi.connection.connection:168 - [198.19.8.4] Connecting as user root
|
| 2025-01-06 13:22:01 [35mDEBUG [0m python_alsi.connection.connection:193 - [198.19.8.4] Connecting directly using ssh
|
| 2025-01-06 13:22:01 [35mDEBUG [0m python_alsi.connection.initialize_pipe:665 - Connection command: ['ssh', '-e', 'none', '-A', '-oControlMaster=auto', '-oControlPersist=10m', '-oControlPath=/home/jdietz/.ssh/controlmasters/None-%r@%h:%p', '-oStrictHostKeyChecking=no', '-oBatchMode=yes', '-l', 'root', '198.19.8.4']
|
| 2025-01-06 13:22:02 [35mDEBUG [0m python_alsi.connection.initialize_pipe:669 - Established contact with 198.19.8.4
|
| 2025-01-06 13:22:02 [35mDEBUG [0m python_alsi.connection._setup_rpyc:485 - Waiting for remote shell.
|
| 2025-01-06 13:22:02 [35mDEBUG [0m python_alsi.connection._setup_rpyc:492 - Starting up rpyc on the remote machine (Python: /usr/local/akamai/bin/python3.11).
|
| 2025-01-06 13:22:02 [35mDEBUG [0m python_alsi.connection.__init__:685 - Connecting to remote rpyc server with: ['ssh', '-e', 'none', '-A', '-oControlMaster=auto', '-oControlPersist=10m', '-oControlPath=/home/jdietz/.ssh/controlmasters/None-%r@%h:%p', '-oStrictHostKeyChecking=no', '-oBatchMode=yes', '-l', 'root', '198.19.8.4', 'sh', '-c', '"echo SYNC0;exec sh"']
|
| 2025-01-06 13:22:03 [35mDEBUG [0m python_alsi.connection.__init__:696 - Connected.
|
| 2025-01-06 13:22:04 [35mDEBUG [0m python_alsi.machine.run_cmd:249 - [198.19.8.4] Running 'ls /a/ssl-rotation-manager/state/*.json' as root
|
| 2025-01-06 13:22:04 [35mDEBUG [0m root.mdtserver_machines_fixture:122 - Created instance: MdtServerMachine: ip=198.19.8.4, network=metanet, testnet=sqa2, role=server
|
| 2025-01-06 13:22:04 [35mDEBUG [0m python_alsi.util.__call__:474 - Creating a new instance of MdtServerMachine for key network=<python_alsi.network.DirectNetwork object at 0x7f4a9dc94750>,ip=198.19.8.5
|
| 2025-01-06 13:22:04 [35mDEBUG [0m python_alsi.util.__call__:474 - Creating a new instance of ConnManager for key ip=198.19.8.5,nat_gateway=None,authgate=None
|
| 2025-01-06 13:22:04 [35mDEBUG [0m python_alsi.machine.run_cmd:249 - [198.19.8.5] Running 'ls /a/ssl-rotation-manager/conf/*.json' as root
|
| 2025-01-06 13:22:04 [32mINFO [0m python_alsi.connection.connection:168 - [198.19.8.5] Connecting as user root
|
| 2025-01-06 13:22:04 [35mDEBUG [0m python_alsi.connection.connection:193 - [198.19.8.5] Connecting directly using ssh
|
| 2025-01-06 13:22:04 [35mDEBUG [0m python_alsi.connection.initialize_pipe:665 - Connection command: ['ssh', '-e', 'none', '-A', '-oControlMaster=auto', '-oControlPersist=10m', '-oControlPath=/home/jdietz/.ssh/controlmasters/None-%r@%h:%p', '-oStrictHostKeyChecking=no', '-oBatchMode=yes', '-l', 'root', '198.19.8.5']
|
| 2025-01-06 13:22:04 [35mDEBUG [0m python_alsi.connection.initialize_pipe:669 - Established contact with 198.19.8.5
|
| 2025-01-06 13:22:04 [35mDEBUG [0m python_alsi.connection._setup_rpyc:485 - Waiting for remote shell.
|
| 2025-01-06 13:22:04 [35mDEBUG [0m python_alsi.connection._setup_rpyc:492 - Starting up rpyc on the remote machine (Python: /usr/local/akamai/bin/python3.11).
|
| 2025-01-06 13:22:05 [35mDEBUG [0m python_alsi.connection.__init__:685 - Connecting to remote rpyc server with: ['ssh', '-e', 'none', '-A', '-oControlMaster=auto', '-oControlPersist=10m', '-oControlPath=/home/jdietz/.ssh/controlmasters/None-%r@%h:%p', '-oStrictHostKeyChecking=no', '-oBatchMode=yes', '-l', 'root', '198.19.8.5', 'sh', '-c', '"echo SYNC0;exec sh"']
|
| 2025-01-06 13:22:06 [35mDEBUG [0m python_alsi.connection.__init__:696 - Connected.
|
| 2025-01-06 13:22:06 [35mDEBUG [0m python_alsi.machine.run_cmd:249 - [198.19.8.5] Running 'ls /a/ssl-rotation-manager/state/*.json' as root
|
| 2025-01-06 13:22:07 [35mDEBUG [0m root.mdtserver_machines_fixture:122 - Created instance: MdtServerMachine: ip=198.19.8.5, network=metanet, testnet=sqa2, role=server
|
| 2025-01-06 13:22:07 [35mDEBUG [0m python_alsi.util.__call__:474 - Creating a new instance of MdtServerMachine for key network=<python_alsi.network.DirectNetwork object at 0x7f4a9dc94750>,ip=198.19.8.6
|
| 2025-01-06 13:22:07 [35mDEBUG [0m python_alsi.util.__call__:474 - Creating a new instance of ConnManager for key ip=198.19.8.6,nat_gateway=None,authgate=None
|
| 2025-01-06 13:22:07 [35mDEBUG [0m python_alsi.machine.run_cmd:249 - [198.19.8.6] Running 'ls /a/ssl-rotation-manager/conf/*.json' as root
|
| 2025-01-06 13:22:07 [32mINFO [0m python_alsi.connection.connection:168 - [198.19.8.6] Connecting as user root
|
| 2025-01-06 13:22:07 [35mDEBUG [0m python_alsi.connection.connection:193 - [198.19.8.6] Connecting directly using ssh
|
| 2025-01-06 13:22:07 [35mDEBUG [0m python_alsi.connection.initialize_pipe:665 - Connection command: ['ssh', '-e', 'none', '-A', '-oControlMaster=auto', '-oControlPersist=10m', '-oControlPath=/home/jdietz/.ssh/controlmasters/None-%r@%h:%p', '-oStrictHostKeyChecking=no', '-oBatchMode=yes', '-l', 'root', '198.19.8.6']
|
| 2025-01-06 13:22:07 [35mDEBUG [0m python_alsi.connection.initialize_pipe:669 - Established contact with 198.19.8.6
|
| 2025-01-06 13:22:07 [35mDEBUG [0m python_alsi.connection._setup_rpyc:485 - Waiting for remote shell.
|
| 2025-01-06 13:22:07 [35mDEBUG [0m python_alsi.connection._setup_rpyc:492 - Starting up rpyc on the remote machine (Python: /usr/local/akamai/bin/python3.11).
|
| 2025-01-06 13:22:08 [35mDEBUG [0m python_alsi.connection.__init__:685 - Connecting to remote rpyc server with: ['ssh', '-e', 'none', '-A', '-oControlMaster=auto', '-oControlPersist=10m', '-oControlPath=/home/jdietz/.ssh/controlmasters/None-%r@%h:%p', '-oStrictHostKeyChecking=no', '-oBatchMode=yes', '-l', 'root', '198.19.8.6', 'sh', '-c', '"echo SYNC0;exec sh"']
|
| 2025-01-06 13:22:08 [35mDEBUG [0m python_alsi.connection.__init__:696 - Connected.
|
| 2025-01-06 13:22:09 [35mDEBUG [0m python_alsi.machine.run_cmd:249 - [198.19.8.6] Running 'ls /a/ssl-rotation-manager/state/*.json' as root
|
| 2025-01-06 13:22:09 [35mDEBUG [0m root.mdtserver_machines_fixture:122 - Created instance: MdtServerMachine: ip=198.19.8.6, network=metanet, testnet=sqa2, role=server
|
| 2025-01-06 13:22:09 [35mDEBUG [0m root.mdtserver_machines_fixture:125 - mdtserver_machines fixture initialized with 3 machines
|
| 2025-01-06 13:22:09 [35mDEBUG [0m python_mdt.service.mdtservice.get_config:90 - Fetching current mdtreceiver configuration from service=mdtreceiver, MdtServerMachine: ip=198.19.8.4, network=metanet, testnet=sqa2, role=server
|
| 2025-01-06 13:22:12 [35mDEBUG [0m python_alsi.service.get_local_tableprov_data:404 - Found matching row for machine 198.19.8.4 in table mdtreceiver_status: {'machineip': '198.19.8.4', 'version': '2.16', 'reporting_time': '1736187695', 'client_connection_limit': '110', 'client_connections': '30', 'max_client_connections_1h': '38', 'heap_used': '170917240', 'heap_committed': '1038090240', 'heap_max': '12884901888', 'nonheap_used': '109138256', 'nonheap_committed': '113111040', 'bad_zk_state_1h': '0', 'mdtzookeeper_quorum': 'mdtzookeeper_test.sqa2.qa.akamai.com', 'zk_op_successes_1m': '0', 'zk_op_failures_1m': '0', 'zk_op_errors_1m': '0', 'zk_op_successes_5m': '0', 'zk_op_failures_5m': '0', 'zk_op_errors_5m': '0', 'zk_op_successes_15m': '0', 'zk_op_failures_15m': '0', 'zk_op_errors_15m': '0'}
|
| 2025-01-06 13:22:12 [35mDEBUG [0m python_alsi.machine.run_cmd:249 - [198.19.8.4] Running 'source /usr/local/akamai/etc/akamai.conf; $MDT_JAVA_HOME/bin/keytool -importkeystore -srckeystore /usr/local/akamai/mdtreceiver/etc/keys/api.jks -srcstorepass password -destkeystore /tmp/python-mdt-secrets/api.p12.tmp -deststorepass password -deststoretype pkcs12 -noprompt -provider org.bouncycastle.jcajce.provider.BouncyCastleFipsProvider -providerpath /a/mdtreceiver/lib/bc-fips.jar -srcstoretype BCFKS' as root
|
| 2025-01-06 13:22:14 [35mDEBUG [0m python_alsi.machine.run_cmd:249 - [198.19.8.4] Running 'openssl pkcs12 -in /tmp/python-mdt-secrets/api.p12 -nodes -nocerts -out /tmp/python-mdt-secrets/api.private_key.tmp -passin pass:password' as root
|
| 2025-01-06 13:22:15 [35mDEBUG [0m python_alsi.machine.run_cmd:249 - [198.19.8.4] Running 'openssl pkcs12 -in /tmp/python-mdt-secrets/api.p12 -nodes -nokeys -out /tmp/python-mdt-secrets/api.certificate.tmp -passin pass:password' as root
|
| 2025-01-06 13:22:15 [35mDEBUG [0m root.mdtproducer_machines_fixture:175 - Initializing mdtproducer_machines fixture
|
| 2025-01-06 13:22:15 [32mINFO [0m python_mdt.machine.mdtzookeepermachine.get_mdtzookeeper_quorum:120 - mdtzookeeper quorum 'mdtzookeeper_test.sqa2.qa.akamai.com' is assigned to MDT system 'mdt-test-auto'
|
| 2025-01-06 13:22:15 [32mINFO [0m python_mdt.machine.mdtproducermachine._get_mdtproducer_ensemble_for_mdtzookeeper_quorum:113 - mdtproducer ensemble 'producer_ensemble_test' is assigned to mdtzookeeper quorum 'mdtzookeeper_test.sqa2.qa.akamai.com'
|
| 2025-01-06 13:22:15 [32mINFO [0m python_mdt.machine.mdtproducermachine.get_mdtproducer_machine_info:144 - Determining MDT producer instances for testnet 'sqa2', MDT system 'mdt-test-auto'
|
| 2025-01-06 13:22:15 [35mDEBUG [0m python_alsi.query._refresh_query:201 - Running query on agg-metanet.sqa2.qa.akamai.com: select mdtproducer_node.machineip ip from mdtproducer_node left outer join serviceinfo on mdtproducer_node.machineip = serviceinfo.machineip where serviceinfo.service = 'mdtproducer' and serviceinfo.status = 'up' and mdtproducer_node.ensemble_name = 'producer_ensemble_test'and mdtproducer_node.mdtzookeeper_quorum = 'mdtzookeeper_test.sqa2.qa.akamai.com';
|
| 2025-01-06 13:22:17 [35mDEBUG [0m python_alsi.query._run_query:263 - Command took 1 seconds
|
| 2025-01-06 13:22:17 [35mDEBUG [0m python_alsi.query._handle_result:321 - Caching result.
|
| 2025-01-06 13:22:17 [32mINFO [0m python_mdt.machine.mdtproducermachine.get_mdtproducer_machine_info:153 - Found 2 MDT producer machine(s) for testnet 'sqa2', MDT system 'mdt-test-auto'
|
| 2025-01-06 13:22:17 [35mDEBUG [0m python_alsi.util.__call__:474 - Creating a new instance of MdtProducerMachine for key network=<python_alsi.network.DirectNetwork object at 0x7f4a9dc94750>,ip=198.19.11.119,ensemble=producer_ensemble_test,zk_quorum=mdtzookeeper_test.sqa2.qa.akamai.com
|
| 2025-01-06 13:22:17 [35mDEBUG [0m python_alsi.util.__call__:474 - Creating a new instance of ConnManager for key ip=198.19.11.119,nat_gateway=None,authgate=None
|
| 2025-01-06 13:22:17 [35mDEBUG [0m python_alsi.machine.run_cmd:249 - [198.19.11.119] Running 'ls /a/ssl-rotation-manager/conf/*.json' as root
|
| 2025-01-06 13:22:17 [32mINFO [0m python_alsi.connection.connection:168 - [198.19.11.119] Connecting as user root
|
| 2025-01-06 13:22:17 [35mDEBUG [0m python_alsi.connection.connection:193 - [198.19.11.119] Connecting directly using ssh
|
| 2025-01-06 13:22:17 [35mDEBUG [0m python_alsi.connection.initialize_pipe:665 - Connection command: ['ssh', '-e', 'none', '-A', '-oControlMaster=auto', '-oControlPersist=10m', '-oControlPath=/home/jdietz/.ssh/controlmasters/None-%r@%h:%p', '-oStrictHostKeyChecking=no', '-oBatchMode=yes', '-l', 'root', '198.19.11.119']
|
| 2025-01-06 13:22:18 [35mDEBUG [0m python_alsi.connection.initialize_pipe:669 - Established contact with 198.19.11.119
|
| 2025-01-06 13:22:18 [35mDEBUG [0m python_alsi.connection._setup_rpyc:485 - Waiting for remote shell.
|
| 2025-01-06 13:22:18 [35mDEBUG [0m python_alsi.connection._setup_rpyc:492 - Starting up rpyc on the remote machine (Python: /usr/local/akamai/bin/python3.11).
|
| 2025-01-06 13:22:18 [35mDEBUG [0m python_alsi.connection.__init__:685 - Connecting to remote rpyc server with: ['ssh', '-e', 'none', '-A', '-oControlMaster=auto', '-oControlPersist=10m', '-oControlPath=/home/jdietz/.ssh/controlmasters/None-%r@%h:%p', '-oStrictHostKeyChecking=no', '-oBatchMode=yes', '-l', 'root', '198.19.11.119', 'sh', '-c', '"echo SYNC0;exec sh"']
|
| 2025-01-06 13:22:19 [35mDEBUG [0m python_alsi.connection.__init__:696 - Connected.
|
| 2025-01-06 13:22:20 [35mDEBUG [0m python_alsi.machine.run_cmd:249 - [198.19.11.119] Running 'ls /a/ssl-rotation-manager/state/*.json' as root
|
| 2025-01-06 13:22:20 [35mDEBUG [0m root.mdtproducer_machines_fixture:200 - Created instance: MdtProducerMachine: ip=198.19.11.119, network=metanet, testnet=sqa2, role=producer
|
| 2025-01-06 13:22:20 [35mDEBUG [0m python_alsi.util.__call__:474 - Creating a new instance of MdtProducerMachine for key network=<python_alsi.network.DirectNetwork object at 0x7f4a9dc94750>,ip=198.19.11.120,ensemble=producer_ensemble_test,zk_quorum=mdtzookeeper_test.sqa2.qa.akamai.com
|
| 2025-01-06 13:22:20 [35mDEBUG [0m python_alsi.util.__call__:474 - Creating a new instance of ConnManager for key ip=198.19.11.120,nat_gateway=None,authgate=None
|
| 2025-01-06 13:22:20 [35mDEBUG [0m python_alsi.machine.run_cmd:249 - [198.19.11.120] Running 'ls /a/ssl-rotation-manager/conf/*.json' as root
|
| 2025-01-06 13:22:20 [32mINFO [0m python_alsi.connection.connection:168 - [198.19.11.120] Connecting as user root
|
| 2025-01-06 13:22:20 [35mDEBUG [0m python_alsi.connection.connection:193 - [198.19.11.120] Connecting directly using ssh
|
| 2025-01-06 13:22:20 [35mDEBUG [0m python_alsi.connection.initialize_pipe:665 - Connection command: ['ssh', '-e', 'none', '-A', '-oControlMaster=auto', '-oControlPersist=10m', '-oControlPath=/home/jdietz/.ssh/controlmasters/None-%r@%h:%p', '-oStrictHostKeyChecking=no', '-oBatchMode=yes', '-l', 'root', '198.19.11.120']
|
| 2025-01-06 13:22:20 [35mDEBUG [0m python_alsi.connection.initialize_pipe:669 - Established contact with 198.19.11.120
|
| 2025-01-06 13:22:20 [35mDEBUG [0m python_alsi.connection._setup_rpyc:485 - Waiting for remote shell.
|
| 2025-01-06 13:22:20 [35mDEBUG [0m python_alsi.connection._setup_rpyc:492 - Starting up rpyc on the remote machine (Python: /usr/local/akamai/bin/python3.11).
|
| 2025-01-06 13:22:21 [35mDEBUG [0m python_alsi.connection.__init__:685 - Connecting to remote rpyc server with: ['ssh', '-e', 'none', '-A', '-oControlMaster=auto', '-oControlPersist=10m', '-oControlPath=/home/jdietz/.ssh/controlmasters/None-%r@%h:%p', '-oStrictHostKeyChecking=no', '-oBatchMode=yes', '-l', 'root', '198.19.11.120', 'sh', '-c', '"echo SYNC0;exec sh"']
|
| 2025-01-06 13:22:22 [35mDEBUG [0m python_alsi.connection.__init__:696 - Connected.
|
| 2025-01-06 13:22:22 [35mDEBUG [0m python_alsi.machine.run_cmd:249 - [198.19.11.120] Running 'ls /a/ssl-rotation-manager/state/*.json' as root
|
| 2025-01-06 13:22:23 [35mDEBUG [0m root.mdtproducer_machines_fixture:200 - Created instance: MdtProducerMachine: ip=198.19.11.120, network=metanet, testnet=sqa2, role=producer
|
| 2025-01-06 13:22:23 [35mDEBUG [0m root.mdtproducer_machines_fixture:203 - mdtproducer_machines fixture initialized with 2 machines
|
| 2025-01-06 13:22:23 [35mDEBUG [0m python_alsi.query._refresh_query:201 - Running query on agg-metanet.sqa2.qa.akamai.com: select mmu.machineip ip from mdtagent_memory_usage mmu, whoruns w where mmu.machineip = w.machineip and w.mdtagent_test=1
|
| 2025-01-06 13:22:24 [35mDEBUG [0m python_alsi.query._run_query:263 - Command took 1 seconds
|
| 2025-01-06 13:22:25 [35mDEBUG [0m conftest._mdtagent_test:108 - SQL response: ['198.18.116.168', '198.18.116.169', '198.18.116.170', '198.18.116.171', '198.18.116.172', '198.18.116.173', '198.18.116.174', '198.19.14.196']
|
| 2025-01-06 13:22:25 [35mDEBUG [0m python_alsi.query._refresh_query:201 - Running query on agg-metanet.sqa2.qa.akamai.com: select mmu.machineip ip from mdtagent_memory_usage mmu, whoruns w where mmu.machineip = w.machineip and w.mdtagent_test=1
|
| 2025-01-06 13:22:26 [35mDEBUG [0m python_alsi.query._run_query:263 - Command took 1 seconds
|
| 2025-01-06 13:22:27 [33mWARNING [0m conftest._mdtagent_test:112 - ********* STUB FIXTURE RUNNING RETURNING 198.19.8.7 ***********
|
| 2025-01-06 13:22:27 [35mDEBUG [0m python_alsi.util.__call__:474 - Creating a new instance of NetworkMachine for key network=<python_alsi.network.DirectNetwork object at 0x7f4a9dc94750>,ip=198.19.8.7
|
| 2025-01-06 13:22:27 [35mDEBUG [0m python_alsi.util.__call__:474 - Creating a new instance of ConnManager for key ip=198.19.8.7,nat_gateway=None,authgate=None
|
| 2025-01-06 13:22:27 [32mINFO [0m python_alsi.connection.connection:168 - [198.19.8.7] Connecting as user root
|
| 2025-01-06 13:22:27 [35mDEBUG [0m python_alsi.connection.connection:193 - [198.19.8.7] Connecting directly using ssh
|
| 2025-01-06 13:22:27 [35mDEBUG [0m python_alsi.connection.initialize_pipe:665 - Connection command: ['ssh', '-e', 'none', '-A', '-oControlMaster=auto', '-oControlPersist=10m', '-oControlPath=/home/jdietz/.ssh/controlmasters/None-%r@%h:%p', '-oStrictHostKeyChecking=no', '-oBatchMode=yes', '-l', 'root', '198.19.8.7']
|
| 2025-01-06 13:22:28 [35mDEBUG [0m python_alsi.connection.initialize_pipe:669 - Established contact with 198.19.8.7
|
| 2025-01-06 13:22:28 [35mDEBUG [0m python_alsi.connection._setup_rpyc:485 - Waiting for remote shell.
|
| 2025-01-06 13:22:28 [35mDEBUG [0m python_alsi.connection._setup_rpyc:492 - Starting up rpyc on the remote machine (Python: /usr/local/akamai/bin/python3.11).
|
| 2025-01-06 13:22:28 [35mDEBUG [0m python_alsi.connection.__init__:685 - Connecting to remote rpyc server with: ['ssh', '-e', 'none', '-A', '-oControlMaster=auto', '-oControlPersist=10m', '-oControlPath=/home/jdietz/.ssh/controlmasters/None-%r@%h:%p', '-oStrictHostKeyChecking=no', '-oBatchMode=yes', '-l', 'root', '198.19.8.7', 'sh', '-c', '"echo SYNC0;exec sh"']
|
| 2025-01-06 13:22:29 [35mDEBUG [0m python_alsi.connection.__init__:696 - Connected.
|
| 2025-01-06 13:22:31 [35mDEBUG [0m python_alsi.service.get_local_tableprov_data:404 - Found matching row for machine 198.19.8.7 in table mdtagent_memory_usage: {'machineip': '198.19.8.7', 'version': 'mdtagent-3.7', 'uptime': '330079', 'heap_used': '160849488', 'heap_committed': '419430400', 'heap_max': '419430400', 'nonheap_used': '52889680', 'nonheap_committed': '55115776', 'num_threads': '43', 'jetsagent_connected': '0', 'fast_trigger_arrivals_10m': '0', 'fast_trigger_activations_10m': '0', 'slow_trigger_activations_10m': '0', 'dag_mode_enabled': '1'}
|
| 2025-01-06 13:22:31 [35mDEBUG [0m python_alsi.service.backup_config_file:268 - Backing up /a/mdtagent/etc/mdtagent.conf to /a/mdtagent/etc/mdtagent.bak for service=mdtagent, NetworkMachine: ip=198.19.8.7, network=metanet, testnet=sqa2
|
| 2025-01-06 13:22:33 [32mINFO [0m python_mdt.service.mdtagent._update_scalar_config:392 - Updating mdtagent attribute download_ip_ttl from 60 to 20 on machine 198.19.8.7
|
| 2025-01-06 13:22:34 [32mINFO [0m python_alsi.service.restart:130 - Restarting service mdtagent
|
| 2025-01-06 13:22:34 [35mDEBUG [0m python_alsi.machine.run_cmd:249 - [198.19.8.7] Running '/a/sbin/akamai_run restart mdtagent' as root
|
| 2025-01-06 13:22:35 [35mDEBUG [0m python_alsi.machine.run_cmd:249 - [198.19.8.7] Running '/a/sbin/akamai_run check mdtagent' as root
|
| 2025-01-06 13:22:36 [32mINFO [0m python_alsi.service.wait_for_service_up:158 - mdtagent service is up
|
| 2025-01-06 13:22:36 [32mINFO [0m python_alsi.util.logged_sleep:43 - Sleeping 15 seconds for mdtagent to complete restart.
|
| ---------------------------------------------------------------------------------------- live log call -----------------------------------------------------------------------------------------
|
| 2025-01-06 13:22:51 [32mINFO [0m root.pytest_runtest_call:27 - ==================== Start of test: 'test_large_bundle_envelope_processing' ====================
|
| 2025-01-06 13:22:51 [32mINFO [0m conftest._dir_test_channel:192 - ****** MDT SYSTEM: mdt-test-auto
|
| 2025-01-06 13:22:52 [35mDEBUG [0m python_alsi.machine.request:750 - Issuing DELETE HTTP request with url=/mdt/v1/channels/test.multi_2.dir.producer_set_2.mdtagent_envelope_size?zone=1
|
| 2025-01-06 13:22:53 [35mDEBUG [0m python_alsi.machine.request:757 - Received 200 HTTP response for request url=/mdt/v1/channels/test.multi_2.dir.producer_set_2.mdtagent_envelope_size?zone=1
|
| 2025-01-06 13:22:53 [35mDEBUG [0m python_alsi.machine.run_cmd:249 - [198.19.8.7] Running 'find /a/mdtagent/var/dag -name test.multi_2.dir.producer_set_2.mdtagent_envelope_size -print' as root
|
| 2025-01-06 13:22:54 [35mDEBUG [0m python_alsi.util.__call__:474 - Creating a new instance of DagObjectStore for key managed_service=service=mdtagent, NetworkMachine: ip=198.19.8.7, network=metanet, testnet=sqa2,dag_object_store_location=/a/mdtagent/var/dag/usr/local/akamai/etc/test.multi_2.dir.producer_set_2.mdtagent_envelope_size
|
| 2025-01-06 13:22:54 [35mDEBUG [0m python_mdt.service.mdtagent.get_dag_object_store:500 - DAG object store for channel test.multi_2.dir.producer_set_2.mdtagent_envelope_size.1 is /a/mdtagent/var/dag/usr/local/akamai/etc/test.multi_2.dir.producer_set_2.mdtagent_envelope_size
|
| 2025-01-06 13:22:54 [35mDEBUG [0m python_mdt.service.mdtagent.clear_dag_object_store:535 - Clearing DAG directory /a/mdtagent/var/dag/usr/local/akamai/etc/test.multi_2.dir.producer_set_2.mdtagent_envelope_size and files for channel test.multi_2.dir.producer_set_2.mdtagent_envelope_size
|
| 2025-01-06 13:22:57 [35mDEBUG [0m python_mdt.service.mdtagent.clear_destination_files:563 - Removing files directory /a/etc/test.multi_2.dir.producer_set_2.mdtagent_envelope_size and files for channel test.multi_2.dir.producer_set_2.mdtagent_envelope_size
|
| 2025-01-06 13:23:00 [32mINFO [0m python_mdt.service.mdtagent.subscribe_to_channel:350 - Adding channel name test.multi_2.dir.producer_set_2.mdtagent_envelope_size to group tests in system mdt-test-auto
|
| 2025-01-06 13:23:01 [32mINFO [0m python_alsi.service.restart:130 - Restarting service mdtagent
|
| 2025-01-06 13:23:01 [35mDEBUG [0m python_alsi.machine.run_cmd:249 - [198.19.8.7] Running '/a/sbin/akamai_run restart mdtagent' as root
|
| 2025-01-06 13:23:02 [35mDEBUG [0m python_alsi.machine.run_cmd:249 - [198.19.8.7] Running '/a/sbin/akamai_run check mdtagent' as root
|
| 2025-01-06 13:23:03 [32mINFO [0m python_alsi.service.wait_for_service_up:158 - mdtagent service is up
|
| 2025-01-06 13:23:03 [32mINFO [0m python_alsi.util.logged_sleep:43 - Sleeping 15 seconds for mdtagent to complete restart.
|
| 2025-01-06 13:23:19 [35mDEBUG [0m python_mdt.service.mdtagent.clear_persistent_state:517 - Removing persistent state at /a/mdtagent/var/persist/usr/local/akamai/etc/test.multi_2.dir.producer_set_2.mdtagent_envelope_size for channel test.multi_2.dir.producer_set_2.mdtagent_envelope_size.1
|
| 2025-01-06 13:23:21 [32mINFO [0m python_mdt.service.mdtagent._update_scalar_config:403 - Mdtagent attribute download_ip_ttl already set to 20 on machine 198.19.8.7; no config change needed
|
| 2025-01-06 13:23:22 [35mDEBUG [0m python_alsi.service.get_local_tableprov_data:404 - Found matching row for machine 198.19.11.119 in table mdtproducer_node: {'machineip': '198.19.11.119', 'version': 'mdtproducer-1.10', 'producer_name': 'producer1-test', 'ensemble_name': 'producer_ensemble_test', 'producer_set_index': '1', 'stager_set_index': '0', 'group_indexes_publish_stager_sets': '0', 'mdtzookeeper_quorum': 'mdtzookeeper_test.sqa2.qa.akamai.com', 'leader_status': 'leader', 'leader_changes_1h': '2'}
|
| 2025-01-06 13:23:24 [35mDEBUG [0m python_alsi.service.get_local_tableprov_data:404 - Found matching row for machine 198.19.11.120 in table mdtproducer_node: {'machineip': '198.19.11.120', 'version': 'mdtproducer-1.10', 'producer_name': 'producer2-test', 'ensemble_name': 'producer_ensemble_test', 'producer_set_index': '2', 'stager_set_index': '0', 'group_indexes_publish_stager_sets': '0', 'mdtzookeeper_quorum': 'mdtzookeeper_test.sqa2.qa.akamai.com', 'leader_status': 'leader', 'leader_changes_1h': '4'}
|
| 2025-01-06 13:23:24 [32mINFO [0m test_envelope.test_large_bundle_envelope_processing:56 - MDT PRODUCER: 198.19.11.120
|
| 2025-01-06 13:23:24 [35mDEBUG [0m python_mdt.service.mdtreceiver.get_group_config:87 - Fetching current mdtreceiver group configuration from service=mdtreceiver, MdtServerMachine: ip=198.19.8.4, network=metanet, testnet=sqa2, role=server
|
| 2025-01-06 13:23:24 [35mDEBUG [0m python_mdt.service.mdtservice.get_config:90 - Fetching current mdtreceiver configuration from service=mdtreceiver, MdtServerMachine: ip=198.19.8.4, network=metanet, testnet=sqa2, role=server
|
| 2025-01-06 13:23:26 [35mDEBUG [0m python_mdt.service.mdtreceiver.get_group_config:87 - Fetching current mdtreceiver group configuration from service=mdtreceiver, MdtServerMachine: ip=198.19.8.4, network=metanet, testnet=sqa2, role=server
|
| 2025-01-06 13:23:28 [35mDEBUG [0m python_alsi.service.get_local_tableprov_data:404 - Found matching row for machine 198.19.8.4 in table mdtreceiver_status: {'machineip': '198.19.8.4', 'version': '2.16', 'reporting_time': '1736187755', 'client_connection_limit': '110', 'client_connections': '30', 'max_client_connections_1h': '38', 'heap_used': '170917240', 'heap_committed': '1038090240', 'heap_max': '12884901888', 'nonheap_used': '109138256', 'nonheap_committed': '113111040', 'bad_zk_state_1h': '0', 'mdtzookeeper_quorum': 'mdtzookeeper_test.sqa2.qa.akamai.com', 'zk_op_successes_1m': '0', 'zk_op_failures_1m': '0', 'zk_op_errors_1m': '0', 'zk_op_successes_5m': '0', 'zk_op_failures_5m': '0', 'zk_op_errors_5m': '0', 'zk_op_successes_15m': '0', 'zk_op_failures_15m': '0', 'zk_op_errors_15m': '0'}
|
| 2025-01-06 13:23:28 [35mDEBUG [0m python_alsi.machine.run_cmd:249 - [198.19.8.4] Running 'source /usr/local/akamai/etc/akamai.conf; $MDT_JAVA_HOME/bin/keytool -importkeystore -srckeystore /usr/local/akamai/mdtreceiver/etc/keys/api.jks -srcstorepass password -destkeystore /tmp/python-mdt-secrets/api.p12.tmp -deststorepass password -deststoretype pkcs12 -noprompt -provider org.bouncycastle.jcajce.provider.BouncyCastleFipsProvider -providerpath /a/mdtreceiver/lib/bc-fips.jar -srcstoretype BCFKS' as root
|
| 2025-01-06 13:23:31 [35mDEBUG [0m python_alsi.machine.run_cmd:249 - [198.19.8.4] Running 'openssl pkcs12 -in /tmp/python-mdt-secrets/api.p12 -nodes -nocerts -out /tmp/python-mdt-secrets/api.private_key.tmp -passin pass:password' as root
|
| 2025-01-06 13:23:31 [35mDEBUG [0m python_alsi.machine.run_cmd:249 - [198.19.8.4] Running 'openssl pkcs12 -in /tmp/python-mdt-secrets/api.p12 -nodes -nokeys -out /tmp/python-mdt-secrets/api.certificate.tmp -passin pass:password' as root
|
| 2025-01-06 13:23:32 [32mINFO [0m python_mdt.machine.mdtmachine.submit_and_verify_json_file_channel:73 - Pushing JSON configuration to channel 'mdt.config.groups'
|
| 2025-01-06 13:23:32 [35mDEBUG [0m python_alsi.machine.request:750 - Issuing POST HTTP request with url=/mdt/v1/channels/mdt.config.groups?zone=1&submitType=full
|
| 2025-01-06 13:23:34 [35mDEBUG [0m python_alsi.machine.request:757 - Received 201 HTTP response for request url=/mdt/v1/channels/mdt.config.groups?zone=1&submitType=full
|
| 2025-01-06 13:23:34 [35mDEBUG [0m python_alsi.machine.request:750 - Issuing PUT HTTP request with url=/mdt/v1/channels/mdt.config.groups?zone=2&uuid=mdt.config.groups.1.0000001736187813.mdt-test-1
|
| 2025-01-06 13:23:36 [35mDEBUG [0m python_alsi.machine.request:757 - Received 201 HTTP response for request url=/mdt/v1/channels/mdt.config.groups?zone=2&uuid=mdt.config.groups.1.0000001736187813.mdt-test-1
|
| 2025-01-06 13:23:36 [35mDEBUG [0m python_alsi.machine.request:750 - Issuing PUT HTTP request with url=/mdt/v1/channels/mdt.config.groups?zone=3&uuid=mdt.config.groups.1.0000001736187813.mdt-test-1
|
| 2025-01-06 13:23:37 [35mDEBUG [0m python_alsi.machine.request:757 - Received 201 HTTP response for request url=/mdt/v1/channels/mdt.config.groups?zone=3&uuid=mdt.config.groups.1.0000001736187813.mdt-test-1
|
| 2025-01-06 13:23:38 [32mINFO [0m python_mdt.machine.mdtmachine.submit_and_verify_json_file_channel:76 - Verifying channel mdt.config.groups has been updated to timestamp 1736187813 on MdtServerMachine: ip=198.19.8.4, network=metanet, testnet=sqa2, role=server
|
| 2025-01-06 13:23:39 [35mDEBUG [0m python_mdt.service.mdtagent.get_persistent_state:244 - On machine 198.19.8.4, watching persistent state file '/a/mdtagent/var/persist/usr/local/akamai/mdtreceiver/etc/mdt.config.groups' for channel 'mdt.config.groups' to see that the channel has been updated to at least the latest timestamp 1736187813
|
| 2025-01-06 13:23:42 [35mDEBUG [0m python_mdt.service.mdtagent.get_persistent_state:259 - Persistent state content for channel 'mdt.config.groups' is: {"sha256": "2c6e6e153aa6e44fd1eb1cffd054baa2750c0bc4f43e1806d9b40b84e166c17b", "destFile": "/usr/local/akamai/mdtreceiver/etc/mdt.config.groups", "contentVersion": "1.3", "channel": "mdt.config.groups", "group": "mdt_config", "zone": 3, "localTimestamp": 1736185629, "numBadAcks": 0, "mdtTimestamp": 1736185601, "mdtTimestampMillisPart": 0}
|
| 2025-01-06 13:23:42 [35mDEBUG [0m python_mdt.service.mdtagent.get_persistent_state:271 - Channel mdt.config.groups has not yet been updated to the requested timestamp 1736187813 or higher (current=1736185601); sleeping 10s (600s remaining)
|
| 2025-01-06 13:23:55 [35mDEBUG [0m python_mdt.service.mdtagent.get_persistent_state:259 - Persistent state content for channel 'mdt.config.groups' is: {"sha256": "8f187a1100050e7e4bbd5a9d0a194822c8b57d15e4e9edf7aed175962affa08c", "destFile": "/usr/local/akamai/mdtreceiver/etc/mdt.config.groups", "contentVersion": "1.3", "channel": "mdt.config.groups", "group": "mdt_config", "zone": 3, "localTimestamp": 1736187835, "numBadAcks": 0, "mdtTimestamp": 1736187813, "mdtTimestampMillisPart": 0}
|
| 2025-01-06 13:23:55 [32mINFO [0m python_mdt.service.mdtagent.get_persistent_state:268 - Channel mdt.config.groups is up to date with requested timestamp 1736187813
|
| 2025-01-06 13:23:55 [32mINFO [0m python_mdt.service.mdtagent.verify_channel_state:302 - Channel mdt.config.groups was downloaded (and optionally notified) successfully for timestamp 1736187813 on service=mdtagent, MdtServerMachine: ip=198.19.8.4, network=metanet, testnet=sqa2, role=server
|
| 2025-01-06 13:23:55 [32mINFO [0m python_mdt.service.mdtagent._update_scalar_config:403 - Mdtagent attribute download_ip_ttl already set to 20 on machine 198.19.8.7; no config change needed
|
| 2025-01-06 13:23:55 [35mDEBUG [0m test_envelope.test_large_bundle_envelope_processing:72 - Add files to channel test.multi_2.dir.producer_set_2.mdtagent_envelope_size.1
|
| 2025-01-06 13:23:55 [32mINFO [0m src.mdt.submitter.add_and_submit_known_files_dir:186 - Generating 3 files of size 1000000 with known filenames - file stem envelope_size for channel test.multi_2.dir.producer_set_2.mdtagent_envelope_size
|
| 2025-01-06 13:23:55 [32mINFO [0m python_mdt.channel.content.add_file_with_random_content:68 - Added file envelope_size.0 as a 1000000 byte random text file
|
| 2025-01-06 13:23:55 [32mINFO [0m python_mdt.channel.content.add_file_with_random_content:68 - Added file envelope_size.1 as a 1000000 byte random text file
|
| 2025-01-06 13:23:55 [32mINFO [0m python_mdt.channel.content.add_file_with_random_content:68 - Added file envelope_size.2 as a 1000000 byte random text file
|
| 2025-01-06 13:23:56 [35mDEBUG [0m python_alsi.machine.request:750 - Issuing POST HTTP request with url=/mdt/v1/channels/test.multi_2.dir.producer_set_2.mdtagent_envelope_size?zone=1&submitType=full
|
| 2025-01-06 13:23:58 [35mDEBUG [0m python_alsi.machine.request:757 - Received 201 HTTP response for request url=/mdt/v1/channels/test.multi_2.dir.producer_set_2.mdtagent_envelope_size?zone=1&submitType=full
|
| 2025-01-06 13:23:59 [35mDEBUG [0m src.mdt.submitter.add_and_submit_known_files_dir:200 - Submit response UUID: test.multi_2.dir.producer_set_2.mdtagent_envelope_size.1.0000001736187837.mdt-test-1, request ID REQID-62892a57-50be-4373-95bb-1ee42be9159d-mdt-test-1, timestamp 1736187838
|
| 2025-01-06 13:23:59 [32mINFO [0m python_mdt.service.mdtproducer.verify_completed_build_stats:230 - Trying to verify completed channel build for channel test.multi_2.dir.producer_set_2.mdtagent_envelope_size.1, timestamp 1736187838
|
| 2025-01-06 13:24:00 [32mINFO [0m python_alsi.service.filter_local_tableprov_rows:430 - *** LEAVING, 0 rows returned
|
| 2025-01-06 13:24:00 [33mWARNING [0m python_alsi.util._wrapper:118 - Ignoring exception mdtproducer unable to find channel version 1736187838 for channel test.multi_2.dir.producer_set_2.mdtagent_envelope_size.1 on attempt 0
|
| Traceback (most recent call last):
|
| File "/home/jdietz/.pyenv/versions/myenv11/lib/python3.11/site-packages/python_alsi/util.py", line 116, in _wrapper
|
| return f(*args, **kwargs)
|
| ^^^^^^^^^^^^^^^^^^
|
| File "/home/jdietz/.pyenv/versions/myenv11/lib/python3.11/site-packages/python_mdt/service/mdtproducer.py", line 241, in verify_completed_build_stats
|
| raise RuntimeError(f"mdtproducer unable to find channel version {timestamp_secs} for channel {channel_id}", )
|
| RuntimeError: mdtproducer unable to find channel version 1736187838 for channel test.multi_2.dir.producer_set_2.mdtagent_envelope_size.1
|
| 2025-01-06 13:24:10 [32mINFO [0m python_mdt.service.mdtproducer.verify_completed_build_stats:230 - Trying to verify completed channel build for channel test.multi_2.dir.producer_set_2.mdtagent_envelope_size.1, timestamp 1736187838
|
| 2025-01-06 13:24:11 [32mINFO [0m python_alsi.service.filter_local_tableprov_rows:423 - ******* NAME: test.multi_2.dir.producer_set_2.mdtagent_envelope_size, TYPE: incremental, TS: 1736187838
|
| 2025-01-06 13:24:11 [32mINFO [0m python_alsi.service.filter_local_tableprov_rows:428 - ******* Matching row NAME: test.multi_2.dir.producer_set_2.mdtagent_envelope_size, TYPE: incremental, TS: 1736187838
|
| 2025-01-06 13:24:11 [32mINFO [0m python_alsi.service.filter_local_tableprov_rows:423 - ******* NAME: test.multi_2.dir.producer_set_2.mdtagent_envelope_size, TYPE: baseline, TS: 1736187838
|
| 2025-01-06 13:24:11 [32mINFO [0m python_alsi.service.filter_local_tableprov_rows:430 - *** LEAVING, 1 rows returned
|
| 2025-01-06 13:24:11 [32mINFO [0m python_mdt.service.mdtproducer.verify_completed_build_stats:238 - Returning 1 entries from completed build table
|
| 2025-01-06 13:24:11 [35mDEBUG [0m test_envelope.test_large_bundle_envelope_processing:80 - Add files to channel test.multi_2.dir.producer_set_2.mdtagent_envelope_size.1
|
| 2025-01-06 13:24:11 [32mINFO [0m src.mdt.submitter.add_and_submit_known_files_dir:186 - Generating 3 files of size 4194304 with known filenames - file stem envelope_size for channel test.multi_2.dir.producer_set_2.mdtagent_envelope_size
|
| 2025-01-06 13:24:11 [32mINFO [0m python_mdt.channel.content.add_file_with_random_content:68 - Added file envelope_size.0 as a 4194304 byte random text file
|
| 2025-01-06 13:24:12 [32mINFO [0m python_mdt.channel.content.add_file_with_random_content:68 - Added file envelope_size.1 as a 4194304 byte random text file
|
| 2025-01-06 13:24:12 [32mINFO [0m python_mdt.channel.content.add_file_with_random_content:68 - Added file envelope_size.2 as a 4194304 byte random text file
|
| 2025-01-06 13:24:12 [35mDEBUG [0m python_alsi.machine.request:750 - Issuing POST HTTP request with url=/mdt/v1/channels/test.multi_2.dir.producer_set_2.mdtagent_envelope_size?zone=1&submitType=incr_lenient
|
| 2025-01-06 13:24:17 [35mDEBUG [0m python_alsi.machine.request:757 - Received 201 HTTP response for request url=/mdt/v1/channels/test.multi_2.dir.producer_set_2.mdtagent_envelope_size?zone=1&submitType=incr_lenient
|
| 2025-01-06 13:24:18 [35mDEBUG [0m src.mdt.submitter.add_and_submit_known_files_dir:200 - Submit response UUID: test.multi_2.dir.producer_set_2.mdtagent_envelope_size.1.0000001736187856.mdt-test-1, request ID REQID-3758f144-461b-4d75-b42e-6b4e7b42e37b-mdt-test-1, timestamp 1736187857
|
| 2025-01-06 13:24:18 [32mINFO [0m python_mdt.service.mdtproducer.verify_completed_build_stats:230 - Trying to verify completed channel build for channel test.multi_2.dir.producer_set_2.mdtagent_envelope_size.1, timestamp 1736187857
|
| 2025-01-06 13:24:19 [32mINFO [0m python_alsi.service.filter_local_tableprov_rows:423 - ******* NAME: test.multi_2.dir.producer_set_2.mdtagent_envelope_size, TYPE: incremental, TS: 1736187838
|
| 2025-01-06 13:24:19 [32mINFO [0m python_alsi.service.filter_local_tableprov_rows:423 - ******* NAME: test.multi_2.dir.producer_set_2.mdtagent_envelope_size, TYPE: baseline, TS: 1736187838
|
| 2025-01-06 13:24:19 [32mINFO [0m python_alsi.service.filter_local_tableprov_rows:430 - *** LEAVING, 0 rows returned
|
| 2025-01-06 13:24:19 [33mWARNING [0m python_alsi.util._wrapper:118 - Ignoring exception mdtproducer unable to find channel version 1736187857 for channel test.multi_2.dir.producer_set_2.mdtagent_envelope_size.1 on attempt 0
|
| Traceback (most recent call last):
|
| File "/home/jdietz/.pyenv/versions/myenv11/lib/python3.11/site-packages/python_alsi/util.py", line 116, in _wrapper
|
| return f(*args, **kwargs)
|
| ^^^^^^^^^^^^^^^^^^
|
| File "/home/jdietz/.pyenv/versions/myenv11/lib/python3.11/site-packages/python_mdt/service/mdtproducer.py", line 241, in verify_completed_build_stats
|
| raise RuntimeError(f"mdtproducer unable to find channel version {timestamp_secs} for channel {channel_id}", )
|
| RuntimeError: mdtproducer unable to find channel version 1736187857 for channel test.multi_2.dir.producer_set_2.mdtagent_envelope_size.1
|
| 2025-01-06 13:24:29 [32mINFO [0m python_mdt.service.mdtproducer.verify_completed_build_stats:230 - Trying to verify completed channel build for channel test.multi_2.dir.producer_set_2.mdtagent_envelope_size.1, timestamp 1736187857
|
| 2025-01-06 13:24:30 [32mINFO [0m python_alsi.service.filter_local_tableprov_rows:423 - ******* NAME: test.multi_2.dir.producer_set_2.mdtagent_envelope_size, TYPE: incremental, TS: 1736187838
|
| 2025-01-06 13:24:30 [32mINFO [0m python_alsi.service.filter_local_tableprov_rows:423 - ******* NAME: test.multi_2.dir.producer_set_2.mdtagent_envelope_size, TYPE: baseline, TS: 1736187838
|
| 2025-01-06 13:24:30 [32mINFO [0m python_alsi.service.filter_local_tableprov_rows:430 - *** LEAVING, 0 rows returned
|
| 2025-01-06 13:24:30 [33mWARNING [0m python_alsi.util._wrapper:118 - Ignoring exception mdtproducer unable to find channel version 1736187857 for channel test.multi_2.dir.producer_set_2.mdtagent_envelope_size.1 on attempt 1
|
| Traceback (most recent call last):
|
| File "/home/jdietz/.pyenv/versions/myenv11/lib/python3.11/site-packages/python_alsi/util.py", line 116, in _wrapper
|
| return f(*args, **kwargs)
|
| ^^^^^^^^^^^^^^^^^^
|
| File "/home/jdietz/.pyenv/versions/myenv11/lib/python3.11/site-packages/python_mdt/service/mdtproducer.py", line 241, in verify_completed_build_stats
|
| raise RuntimeError(f"mdtproducer unable to find channel version {timestamp_secs} for channel {channel_id}", )
|
| RuntimeError: mdtproducer unable to find channel version 1736187857 for channel test.multi_2.dir.producer_set_2.mdtagent_envelope_size.1
|
| 2025-01-06 13:24:40 [32mINFO [0m python_mdt.service.mdtproducer.verify_completed_build_stats:230 - Trying to verify completed channel build for channel test.multi_2.dir.producer_set_2.mdtagent_envelope_size.1, timestamp 1736187857
|
| 2025-01-06 13:24:41 [32mINFO [0m python_alsi.service.filter_local_tableprov_rows:423 - ******* NAME: test.multi_2.dir.producer_set_2.mdtagent_envelope_size, TYPE: incremental, TS: 1736187838
|
| 2025-01-06 13:24:41 [32mINFO [0m python_alsi.service.filter_local_tableprov_rows:423 - ******* NAME: test.multi_2.dir.producer_set_2.mdtagent_envelope_size, TYPE: baseline, TS: 1736187838
|
| 2025-01-06 13:24:41 [32mINFO [0m python_alsi.service.filter_local_tableprov_rows:430 - *** LEAVING, 0 rows returned
|
| 2025-01-06 13:24:41 [33mWARNING [0m python_alsi.util._wrapper:118 - Ignoring exception mdtproducer unable to find channel version 1736187857 for channel test.multi_2.dir.producer_set_2.mdtagent_envelope_size.1 on attempt 2
|
| Traceback (most recent call last):
|
| File "/home/jdietz/.pyenv/versions/myenv11/lib/python3.11/site-packages/python_alsi/util.py", line 116, in _wrapper
|
| return f(*args, **kwargs)
|
| ^^^^^^^^^^^^^^^^^^
|
| File "/home/jdietz/.pyenv/versions/myenv11/lib/python3.11/site-packages/python_mdt/service/mdtproducer.py", line 241, in verify_completed_build_stats
|
| raise RuntimeError(f"mdtproducer unable to find channel version {timestamp_secs} for channel {channel_id}", )
|
| RuntimeError: mdtproducer unable to find channel version 1736187857 for channel test.multi_2.dir.producer_set_2.mdtagent_envelope_size.1
|
| 2025-01-06 13:24:51 [32mINFO [0m python_mdt.service.mdtproducer.verify_completed_build_stats:230 - Trying to verify completed channel build for channel test.multi_2.dir.producer_set_2.mdtagent_envelope_size.1, timestamp 1736187857
|
| 2025-01-06 13:24:52 [32mINFO [0m python_alsi.service.filter_local_tableprov_rows:423 - ******* NAME: test.multi_2.dir.producer_set_2.mdtagent_envelope_size, TYPE: incremental, TS: 1736187838
|
| 2025-01-06 13:24:52 [32mINFO [0m python_alsi.service.filter_local_tableprov_rows:423 - ******* NAME: test.multi_2.dir.producer_set_2.mdtagent_envelope_size, TYPE: baseline, TS: 1736187838
|
| 2025-01-06 13:24:52 [32mINFO [0m python_alsi.service.filter_local_tableprov_rows:430 - *** LEAVING, 0 rows returned
|
| 2025-01-06 13:24:52 [33mWARNING [0m python_alsi.util._wrapper:118 - Ignoring exception mdtproducer unable to find channel version 1736187857 for channel test.multi_2.dir.producer_set_2.mdtagent_envelope_size.1 on attempt 3
|
| Traceback (most recent call last):
|
| File "/home/jdietz/.pyenv/versions/myenv11/lib/python3.11/site-packages/python_alsi/util.py", line 116, in _wrapper
|
| return f(*args, **kwargs)
|
| ^^^^^^^^^^^^^^^^^^
|
| File "/home/jdietz/.pyenv/versions/myenv11/lib/python3.11/site-packages/python_mdt/service/mdtproducer.py", line 241, in verify_completed_build_stats
|
| raise RuntimeError(f"mdtproducer unable to find channel version {timestamp_secs} for channel {channel_id}", )
|
| RuntimeError: mdtproducer unable to find channel version 1736187857 for channel test.multi_2.dir.producer_set_2.mdtagent_envelope_size.1
|
| 2025-01-06 13:25:02 [32mINFO [0m python_mdt.service.mdtproducer.verify_completed_build_stats:230 - Trying to verify completed channel build for channel test.multi_2.dir.producer_set_2.mdtagent_envelope_size.1, timestamp 1736187857
|
| 2025-01-06 13:25:03 [32mINFO [0m python_alsi.service.filter_local_tableprov_rows:423 - ******* NAME: test.multi_2.dir.producer_set_2.mdtagent_envelope_size, TYPE: incremental, TS: 1736187857
|
| 2025-01-06 13:25:03 [32mINFO [0m python_alsi.service.filter_local_tableprov_rows:428 - ******* Matching row NAME: test.multi_2.dir.producer_set_2.mdtagent_envelope_size, TYPE: incremental, TS: 1736187857
|
| 2025-01-06 13:25:03 [32mINFO [0m python_alsi.service.filter_local_tableprov_rows:423 - ******* NAME: test.multi_2.dir.producer_set_2.mdtagent_envelope_size, TYPE: baseline, TS: 1736187838
|
| 2025-01-06 13:25:03 [32mINFO [0m python_alsi.service.filter_local_tableprov_rows:430 - *** LEAVING, 1 rows returned
|
| 2025-01-06 13:25:03 [32mINFO [0m python_mdt.service.mdtproducer.verify_completed_build_stats:238 - Returning 1 entries from completed build table
|
| 2025-01-06 13:25:03 [35mDEBUG [0m test_envelope.test_large_bundle_envelope_processing:87 - Envelope count from larger incremental build: 5
|
| 2025-01-06 13:25:03 [35mDEBUG [0m python_mdt.service.mdtagent.get_persistent_state:244 - On machine 198.19.8.7, watching persistent state file '/a/mdtagent/var/persist/usr/local/akamai/etc/test.multi_2.dir.producer_set_2.mdtagent_envelope_size' for channel 'test.multi_2.dir.producer_set_2.mdtagent_envelope_size' to see that the channel has been updated to at least the latest timestamp 1736187857
|
| 2025-01-06 13:25:06 [35mDEBUG [0m python_mdt.service.mdtagent.get_persistent_state:259 - Persistent state content for channel 'test.multi_2.dir.producer_set_2.mdtagent_envelope_size' is: {"indexContents": {"Format Version": 0, "Entries": {"envelope_size.1": {"sha256": "fe2911b66becf6d66fc9d2fb44bec0b1dbd7783dc9e80e4218a948d0c0940647"}, "envelope_size.0": {"sha256": "53a4794b6651fa4db0a5595bc8ab7be51284f4b60f106276609630eb169d6222"}, "envelope_size.2": {"sha256": "505ad748d589822815d96819bef7488fe44aae8b232aff69cf31492179912ec5"}}}, "firstFileFailed": false, "badDeleteAck": false, "badAckFiles": [], "destFile": "/usr/local/akamai/etc/test.multi_2.dir.producer_set_2.mdtagent_envelope_size", "contentVersion": "1.3", "channel": "test.multi_2.dir.producer_set_2.mdtagent_envelope_size", "group": "tests", "zone": 1, "localTimestamp": 1736187875, "numBadAcks": 0, "mdtTimestamp": 1736187857, "mdtTimestampMillisPart": 0}
|
| 2025-01-06 13:25:06 [32mINFO [0m python_mdt.service.mdtagent.get_persistent_state:268 - Channel test.multi_2.dir.producer_set_2.mdtagent_envelope_size is up to date with requested timestamp 1736187857
|
| 2025-01-06 13:25:06 [32mINFO [0m root.pytest_runtest_makereport:51 - Test 'test_large_bundle_envelope_processing' passed
|
| PASSED [100%]
|
| -------------------------------------------------------------------------------------- live log teardown ---------------------------------------------------------------------------------------
|
| 2025-01-06 13:25:06 [32mINFO [0m root.pytest_runtest_teardown:60 - ==================== End of test: 'test_large_bundle_envelope_processing' ====================
|
| 2025-01-06 13:25:06 [35mDEBUG [0m root._cleanup_stack_generator:372 - Executing 2 function cleanup stack operations
|
| 2025-01-06 13:25:07 [35mDEBUG [0m python_alsi.service.restore_config:241 - Restoring backup '/a/mdtagent/etc/mdtagent.bak' to '/a/mdtagent/etc/mdtagent.conf' on service=mdtagent, NetworkMachine: ip=198.19.8.7, network=metanet, testnet=sqa2
|
| 2025-01-06 13:25:08 [35mDEBUG [0m python_alsi.service.restore_config:243 - Removing backup '/a/mdtagent/etc/mdtagent.bak' for service=mdtagent, NetworkMachine: ip=198.19.8.7, network=metanet, testnet=sqa2
|
| 2025-01-06 13:25:09 [35mDEBUG [0m python_alsi.service.restore_config:246 - Restarting service=mdtagent, NetworkMachine: ip=198.19.8.7, network=metanet, testnet=sqa2
|
| 2025-01-06 13:25:09 [32mINFO [0m python_alsi.service.restart:130 - Restarting service mdtagent
|
| 2025-01-06 13:25:09 [35mDEBUG [0m python_alsi.machine.run_cmd:249 - [198.19.8.7] Running '/a/sbin/akamai_run restart mdtagent' as root
|
| 2025-01-06 13:25:10 [35mDEBUG [0m python_alsi.machine.run_cmd:249 - [198.19.8.7] Running '/a/sbin/akamai_run check mdtagent' as root
|
| 2025-01-06 13:25:10 [32mINFO [0m python_alsi.service.wait_for_service_up:158 - mdtagent service is up
|
| 2025-01-06 13:25:10 [32mINFO [0m python_alsi.util.logged_sleep:43 - Sleeping 15 seconds for service to complete restart.
|
| 2025-01-06 13:25:25 [32mINFO [0m python_mdt.machine.mdtmachine.submit_and_verify_json_file_channel:73 - Pushing JSON configuration to channel 'mdt.config.groups'
|
| 2025-01-06 13:25:26 [35mDEBUG [0m python_alsi.machine.request:750 - Issuing POST HTTP request with url=/mdt/v1/channels/mdt.config.groups?zone=1&submitType=full
|
| 2025-01-06 13:25:27 [35mDEBUG [0m python_alsi.machine.request:757 - Received 201 HTTP response for request url=/mdt/v1/channels/mdt.config.groups?zone=1&submitType=full
|
| 2025-01-06 13:25:28 [35mDEBUG [0m python_alsi.machine.request:750 - Issuing PUT HTTP request with url=/mdt/v1/channels/mdt.config.groups?zone=2&uuid=mdt.config.groups.1.0000001736187927.mdt-test-1
|
| 2025-01-06 13:25:29 [35mDEBUG [0m python_alsi.machine.request:757 - Received 201 HTTP response for request url=/mdt/v1/channels/mdt.config.groups?zone=2&uuid=mdt.config.groups.1.0000001736187927.mdt-test-1
|
| 2025-01-06 13:25:30 [35mDEBUG [0m python_alsi.machine.request:750 - Issuing PUT HTTP request with url=/mdt/v1/channels/mdt.config.groups?zone=3&uuid=mdt.config.groups.1.0000001736187927.mdt-test-1
|
| 2025-01-06 13:25:31 [35mDEBUG [0m python_alsi.machine.request:757 - Received 201 HTTP response for request url=/mdt/v1/channels/mdt.config.groups?zone=3&uuid=mdt.config.groups.1.0000001736187927.mdt-test-1
|
| 2025-01-06 13:25:31 [32mINFO [0m python_mdt.machine.mdtmachine.submit_and_verify_json_file_channel:76 - Verifying channel mdt.config.groups has been updated to timestamp 1736187927 on MdtServerMachine: ip=198.19.8.4, network=metanet, testnet=sqa2, role=server
|
| 2025-01-06 13:25:31 [35mDEBUG [0m python_mdt.service.mdtagent.get_persistent_state:244 - On machine 198.19.8.4, watching persistent state file '/a/mdtagent/var/persist/usr/local/akamai/mdtreceiver/etc/mdt.config.groups' for channel 'mdt.config.groups' to see that the channel has been updated to at least the latest timestamp 1736187927
|
| 2025-01-06 13:25:34 [35mDEBUG [0m python_mdt.service.mdtagent.get_persistent_state:259 - Persistent state content for channel 'mdt.config.groups' is: {"sha256": "8f187a1100050e7e4bbd5a9d0a194822c8b57d15e4e9edf7aed175962affa08c", "destFile": "/usr/local/akamai/mdtreceiver/etc/mdt.config.groups", "contentVersion": "1.3", "channel": "mdt.config.groups", "group": "mdt_config", "zone": 3, "localTimestamp": 1736187835, "numBadAcks": 0, "mdtTimestamp": 1736187813, "mdtTimestampMillisPart": 0}
|
| 2025-01-06 13:25:34 [35mDEBUG [0m python_mdt.service.mdtagent.get_persistent_state:271 - Channel mdt.config.groups has not yet been updated to the requested timestamp 1736187927 or higher (current=1736187813); sleeping 10s (600s remaining)
|
| 2025-01-06 13:25:47 [35mDEBUG [0m python_mdt.service.mdtagent.get_persistent_state:259 - Persistent state content for channel 'mdt.config.groups' is: {"sha256": "8f187a1100050e7e4bbd5a9d0a194822c8b57d15e4e9edf7aed175962affa08c", "destFile": "/usr/local/akamai/mdtreceiver/etc/mdt.config.groups", "contentVersion": "1.3", "channel": "mdt.config.groups", "group": "mdt_config", "zone": 3, "localTimestamp": 1736187835, "numBadAcks": 0, "mdtTimestamp": 1736187813, "mdtTimestampMillisPart": 0}
|
| 2025-01-06 13:25:47 [35mDEBUG [0m python_mdt.service.mdtagent.get_persistent_state:271 - Channel mdt.config.groups has not yet been updated to the requested timestamp 1736187927 or higher (current=1736187813); sleeping 10s (590s remaining)
|
| 2025-01-06 13:26:00 [35mDEBUG [0m python_mdt.service.mdtagent.get_persistent_state:259 - Persistent state content for channel 'mdt.config.groups' is: {"sha256": "e802422968663bb2d6f05e250f64243127e9653e064b06c6c9234776bfe44b54", "destFile": "/usr/local/akamai/mdtreceiver/etc/mdt.config.groups", "contentVersion": "1.3", "channel": "mdt.config.groups", "group": "mdt_config", "zone": 3, "localTimestamp": 1736187952, "numBadAcks": 0, "mdtTimestamp": 1736187927, "mdtTimestampMillisPart": 0}
|
| 2025-01-06 13:26:00 [32mINFO [0m python_mdt.service.mdtagent.get_persistent_state:268 - Channel mdt.config.groups is up to date with requested timestamp 1736187927
|
| 2025-01-06 13:26:00 [32mINFO [0m python_mdt.service.mdtagent.verify_channel_state:302 - Channel mdt.config.groups was downloaded (and optionally notified) successfully for timestamp 1736187927 on service=mdtagent, MdtServerMachine: ip=198.19.8.4, network=metanet, testnet=sqa2, role=server
|
|
|
|
|
| ================================================================================ [32m [1m1 passed [0m [32m in 248.04s (0:04:08) [0m [32m =================================================================================
|