--Task--
              name: Monitoring_start
           enabled: True
        class_name: MonitoringStart
       source_name: controller
  source_namespace: >default<
       target_name: controller
  target_namespace: >default<
             start: 0.0
              stop: None
           timeout: no timeout
              loop: False
          interval: None
      dependencies: []
          wait_for: []
    preceding_task: None
           options: {}
        group_name: None
       Current dir: /mnt/disks/data/xslou/lodestar-fork/pyrock

________________________________________________________________________________

[2024-07-18 05:36:36] Monitoring_start pre : Initialising task parameters
________________________________________________________________________________

task will be executed on controller (localhost)
________________________________________________________________________________

[2024-07-18 05:36:36] Monitoring_start step1 : N/A
________________________________________________________________________________

2024-07-18 05:37:36,199 INFO    
2024-07-18 05:37:36,200 INFO    ****************************************    Start Lodemon   ****************************************
2024-07-18 05:37:36,324 INFO    
2024-07-18 05:37:36,325 INFO    [loop_until]: kubectl --namespace=xlou --context=gke_engineeringpit_us-east1-d_xlou-cdm delete configmap lodemon-config
2024-07-18 05:37:36,325 INFO    [loop_until]: (max_time=180, interval=5, expected_rc=[0, 1]
2024-07-18 05:37:36,775 INFO    [loop_until]: OK (rc = 0)
2024-07-18 05:37:36,775 DEBUG   --- stdout ---
2024-07-18 05:37:36,775 DEBUG   configmap "lodemon-config" deleted
2024-07-18 05:37:36,776 DEBUG   --- stderr ---
2024-07-18 05:37:36,776 DEBUG   
2024-07-18 05:37:36,776 INFO    
2024-07-18 05:37:36,776 INFO    [loop_until]: kubectl --namespace=xlou --context=gke_engineeringpit_us-east1-d_xlou-cdm create configmap lodemon-config --from-file=/mnt/disks/data/xslou/lodestar-fork/config/config.yaml
2024-07-18 05:37:36,776 INFO    [loop_until]: (max_time=180, interval=5, expected_rc=[0]
2024-07-18 05:37:37,152 INFO    [loop_until]: OK (rc = 0)
2024-07-18 05:37:37,152 DEBUG   --- stdout ---
2024-07-18 05:37:37,153 DEBUG   configmap/lodemon-config created
2024-07-18 05:37:37,153 DEBUG   --- stderr ---
2024-07-18 05:37:37,153 DEBUG   
2024-07-18 05:37:37,155 INFO    
2024-07-18 05:37:37,155 INFO    [run_command]: gcloud iam service-accounts add-iam-policy-binding  pit-test@engineeringpit.iam.gserviceaccount.com                                 --role roles/iam.workloadIdentityUser                                 --member "serviceAccount:engineeringpit.svc.id.goog[xlou/k8s-svc-acct-lodemon]"
2024-07-18 05:37:39,505 ERROR   [run_command]: ERROR
2024-07-18 05:37:39,507 ERROR   --- rc ---
2024-07-18 05:37:39,507 ERROR   returned 1, expected to be in [0]
2024-07-18 05:37:39,507 ERROR   --- stdout ---
2024-07-18 05:37:39,507 ERROR   
2024-07-18 05:37:39,507 ERROR   --- stderr ---
2024-07-18 05:37:39,507 ERROR   ERROR: (gcloud.iam.service-accounts.add-iam-policy-binding) PERMISSION_DENIED: Permission 'iam.serviceAccounts.setIamPolicy' denied on resource (or it may not exist).
- '@type': type.googleapis.com/google.rpc.ErrorInfo
  domain: iam.googleapis.com
  metadata:
    permission: iam.serviceAccounts.setIamPolicy
  reason: IAM_PERMISSION_DENIED
2024-07-18 05:37:39,507 INFO    
2024-07-18 05:37:39,508 WARNING could not add the iam-policy binding to the GSA: pit-test@engineeringpit.iam.gserviceaccount.com for the member k8s-svc-acct-lodemon service account, Identity Cloud metrics will not be present in the Lodemon report.The exception thrown was: (1, , ERROR: (gcloud.iam.service-accounts.add-iam-policy-binding) PERMISSION_DENIED: Permission 'iam.serviceAccounts.setIamPolicy' denied on resource (or it may not exist).
- '@type': type.googleapis.com/google.rpc.ErrorInfo
  domain: iam.googleapis.com
  metadata:
    permission: iam.serviceAccounts.setIamPolicy
  reason: IAM_PERMISSION_DENIED
)
2024-07-18 05:37:39,517 INFO    
2024-07-18 05:37:39,517 INFO    [loop_until]: kubectl --namespace=xlou --context=gke_engineeringpit_us-east1-d_xlou-cdm delete configmap lodemon-deployments
2024-07-18 05:37:39,517 INFO    [loop_until]: (max_time=180, interval=5, expected_rc=[0, 1]
2024-07-18 05:37:39,980 INFO    [loop_until]: OK (rc = 0)
2024-07-18 05:37:39,981 DEBUG   --- stdout ---
2024-07-18 05:37:39,981 DEBUG   configmap "lodemon-deployments" deleted
2024-07-18 05:37:39,981 DEBUG   --- stderr ---
2024-07-18 05:37:39,981 DEBUG   
2024-07-18 05:37:39,981 INFO    
2024-07-18 05:37:39,981 INFO    [loop_until]: kubectl --namespace=xlou --context=gke_engineeringpit_us-east1-d_xlou-cdm create configmap lodemon-deployments --from-file=/mnt/disks/data/xslou/lodestar-fork/config/deployments_to_monitor.yaml
2024-07-18 05:37:39,981 INFO    [loop_until]: (max_time=180, interval=5, expected_rc=[0]
2024-07-18 05:37:40,276 INFO    [loop_until]: OK (rc = 0)
2024-07-18 05:37:40,276 DEBUG   --- stdout ---
2024-07-18 05:37:40,276 DEBUG   configmap/lodemon-deployments created
2024-07-18 05:37:40,276 DEBUG   --- stderr ---
2024-07-18 05:37:40,276 DEBUG   
2024-07-18 05:37:40,276 INFO    
2024-07-18 05:37:40,276 INFO    -------------   Deploy the lodestarbox with lodemon profile   -------------
2024-07-18 05:37:40,277 INFO    
2024-07-18 05:37:40,277 INFO    [run_command]: skaffold deploy --profile lodemon --config=/tmp/tmpqcvcxius --status-check=true --namespace=xlou
2024-07-18 05:37:43,600 INFO    Starting deploy...
2024-07-18 05:37:45,406 INFO    - serviceaccount/k8s-svc-acct-lodemon unchanged
2024-07-18 05:37:45,507 INFO    - clusterrolebinding.rbac.authorization.k8s.io/k8s-svc-acct-crb-xlou unchanged
2024-07-18 05:37:45,607 INFO    - deployment.apps/lodemon configured
2024-07-18 05:37:45,708 INFO    Waiting for deployments to stabilize...
2024-07-18 05:37:50,924 INFO    - xlou:deployment/lodemon: creating container lodemon
2024-07-18 05:37:51,025 INFO    - xlou:pod/lodemon-77dfcdbb7d-vhzq5: creating container lodemon
2024-07-18 05:38:05,867 INFO    - xlou:deployment/lodemon: waiting for rollout to finish: 1 old replicas are pending termination...
2024-07-18 05:38:26,334 INFO    - xlou:deployment/lodemon is ready.
2024-07-18 05:38:26,435 INFO    Deployments stabilized in 40.7 seconds
2024-07-18 05:38:26,536 ERROR   There is a new version (2.12.0) of Skaffold available. Download it from:
2024-07-18 05:38:26,536 ERROR   https://github.com/GoogleContainerTools/skaffold/releases/tag/v2.12.0
2024-07-18 05:38:26,536 ERROR   
2024-07-18 05:38:26,536 ERROR   Help improve Skaffold with our 2-minute anonymous survey: run 'skaffold survey'
2024-07-18 05:38:26,536 ERROR   To help improve the quality of this product, we collect anonymized usage data for details on what is tracked and how we use this data visit <https://skaffold.dev/docs/resources/telemetry/>. This data is handled in accordance with our privacy policy <https://policies.google.com/privacy>
2024-07-18 05:38:26,536 ERROR   
2024-07-18 05:38:26,536 ERROR   You may choose to opt out of this collection by running the following command:
2024-07-18 05:38:26,536 ERROR   skaffold config set --global collect-metrics false
2024-07-18 05:38:26,537 INFO    
2024-07-18 05:38:26,537 INFO    ---------------------   Get expected number of pods   ---------------------
2024-07-18 05:38:26,537 INFO    
2024-07-18 05:38:26,537 INFO    [loop_until]: kubectl --namespace=xlou --context=gke_engineeringpit_us-east1-d_xlou-cdm get deployments --selector app=lodemon --output jsonpath={.items[*].spec.replicas}
2024-07-18 05:38:26,537 INFO    [loop_until]: (max_time=180, interval=5, expected_rc=[0]
2024-07-18 05:38:26,853 INFO    [loop_until]: OK (rc = 0)
2024-07-18 05:38:26,853 DEBUG   --- stdout ---
2024-07-18 05:38:26,853 DEBUG   1
2024-07-18 05:38:26,853 DEBUG   --- stderr ---
2024-07-18 05:38:26,853 DEBUG   
2024-07-18 05:38:26,853 INFO    
2024-07-18 05:38:26,853 INFO    --------------    Reloading pod list for product "lodemon"   --------------
2024-07-18 05:38:26,854 INFO    
2024-07-18 05:38:26,854 INFO    [loop_until]: awk -F" " "{print NF}" <<< `kubectl --namespace=xlou --context=gke_engineeringpit_us-east1-d_xlou-cdm get pods --selector app=lodemon --output jsonpath={.items[*].metadata.name}` | grep 1
2024-07-18 05:38:26,854 INFO    [loop_until]: (max_time=180, interval=10, expected_rc=[0]
2024-07-18 05:38:27,238 INFO    [loop_until]: Function succeeded after 0s (rc=0) - failed to find expected number of element: 1 - retry
2024-07-18 05:38:37,614 INFO    [loop_until]: Function succeeded after 10s (rc=0) - failed to find expected number of element: 1 - retry
2024-07-18 05:38:48,006 INFO    [loop_until]: Function succeeded after 21s (rc=0) - failed to find expected number of element: 1 - retry
2024-07-18 05:38:58,320 INFO    [loop_until]: Function succeeded after 31s (rc=0) - expected number of elements found
2024-07-18 05:38:58,321 INFO    [loop_until]: OK (rc = 0)
2024-07-18 05:38:58,321 DEBUG   --- stdout ---
2024-07-18 05:38:58,321 DEBUG   lodemon-77dfcdbb7d-vhzq5
2024-07-18 05:38:58,321 DEBUG   --- stderr ---
2024-07-18 05:38:58,321 DEBUG   
2024-07-18 05:38:58,321 INFO    
2024-07-18 05:38:58,321 INFO    ------------   Check pod lodemon-77dfcdbb7d-vhzq5 is running   ------------
2024-07-18 05:38:58,321 INFO    
2024-07-18 05:38:58,321 INFO    [loop_until]: kubectl --namespace=xlou --context=gke_engineeringpit_us-east1-d_xlou-cdm get pods lodemon-77dfcdbb7d-vhzq5 -o=jsonpath={.status.phase} | grep "Running"
2024-07-18 05:38:58,321 INFO    [loop_until]: (max_time=360, interval=5, expected_rc=[0]
2024-07-18 05:38:58,656 INFO    [loop_until]: Function succeeded after 0s (rc=0) - expected pattern found
2024-07-18 05:38:58,656 INFO    [loop_until]: OK (rc = 0)
2024-07-18 05:38:58,656 DEBUG   --- stdout ---
2024-07-18 05:38:58,656 DEBUG   Running
2024-07-18 05:38:58,656 DEBUG   --- stderr ---
2024-07-18 05:38:58,656 DEBUG   
2024-07-18 05:38:58,657 INFO    
2024-07-18 05:38:58,657 INFO    [loop_until]: kubectl --namespace=xlou --context=gke_engineeringpit_us-east1-d_xlou-cdm get pods lodemon-77dfcdbb7d-vhzq5 -o=jsonpath={.status.containerStatuses[*].ready} | grep "true"
2024-07-18 05:38:58,657 INFO    [loop_until]: (max_time=360, interval=5, expected_rc=[0]
2024-07-18 05:38:58,972 INFO    [loop_until]: Function succeeded after 0s (rc=0) - expected pattern found
2024-07-18 05:38:58,973 INFO    [loop_until]: OK (rc = 0)
2024-07-18 05:38:58,973 DEBUG   --- stdout ---
2024-07-18 05:38:58,973 DEBUG   true
2024-07-18 05:38:58,973 DEBUG   --- stderr ---
2024-07-18 05:38:58,973 DEBUG   
2024-07-18 05:38:58,973 INFO    
2024-07-18 05:38:58,973 INFO    [loop_until]: kubectl --namespace=xlou --context=gke_engineeringpit_us-east1-d_xlou-cdm get pod lodemon-77dfcdbb7d-vhzq5 --output jsonpath={.status.startTime}
2024-07-18 05:38:58,973 INFO    [loop_until]: (max_time=180, interval=5, expected_rc=[0]
2024-07-18 05:38:59,286 INFO    [loop_until]: OK (rc = 0)
2024-07-18 05:38:59,286 DEBUG   --- stdout ---
2024-07-18 05:38:59,286 DEBUG   2024-07-18T05:37:45Z
2024-07-18 05:38:59,287 DEBUG   --- stderr ---
2024-07-18 05:38:59,287 DEBUG   
2024-07-18 05:38:59,287 INFO    
2024-07-18 05:38:59,287 INFO    -----   Check pod lodemon-77dfcdbb7d-vhzq5 filesystem is accessible   -----
2024-07-18 05:39:00,061 INFO    [loop_until]: Function succeeded after 0s (rc=0) - expected pattern found
2024-07-18 05:39:00,061 INFO    
2024-07-18 05:39:00,061 INFO    ----------    Check pod lodemon-77dfcdbb7d-vhzq5 restart count   ----------
2024-07-18 05:39:00,062 INFO    
2024-07-18 05:39:00,062 INFO    [loop_until]: kubectl --namespace=xlou --context=gke_engineeringpit_us-east1-d_xlou-cdm get pod lodemon-77dfcdbb7d-vhzq5 --output jsonpath={.status.containerStatuses[*].restartCount}
2024-07-18 05:39:00,062 INFO    [loop_until]: (max_time=180, interval=5, expected_rc=[0]
2024-07-18 05:39:00,378 INFO    [loop_until]: OK (rc = 0)
2024-07-18 05:39:00,379 DEBUG   --- stdout ---
2024-07-18 05:39:00,379 DEBUG   0
2024-07-18 05:39:00,379 DEBUG   --- stderr ---
2024-07-18 05:39:00,379 DEBUG   
2024-07-18 05:39:00,379 INFO    Pod lodemon-77dfcdbb7d-vhzq5 has been restarted 0 times.
2024-07-18 05:39:00,379 INFO    
2024-07-18 05:39:00,379 INFO    ---------------------   Get expected number of pods   ---------------------
2024-07-18 05:39:00,380 INFO    
2024-07-18 05:39:00,380 INFO    [loop_until]: kubectl --namespace=xlou --context=gke_engineeringpit_us-east1-d_xlou-cdm get deployments --selector app=lodemon --output jsonpath={.items[*].spec.replicas}
2024-07-18 05:39:00,380 INFO    [loop_until]: (max_time=180, interval=5, expected_rc=[0]
2024-07-18 05:39:00,692 INFO    [loop_until]: OK (rc = 0)
2024-07-18 05:39:00,692 DEBUG   --- stdout ---
2024-07-18 05:39:00,693 DEBUG   1
2024-07-18 05:39:00,693 DEBUG   --- stderr ---
2024-07-18 05:39:00,693 DEBUG   
2024-07-18 05:39:00,693 INFO    
2024-07-18 05:39:00,693 INFO    --------------   Waiting for 1 expected pod(s) to be ready   --------------
2024-07-18 05:39:00,693 INFO    
2024-07-18 05:39:00,693 INFO    [loop_until]: kubectl --namespace=xlou --context=gke_engineeringpit_us-east1-d_xlou-cdm get deployments lodemon --output jsonpath="ready:{.status.readyReplicas} replicas:{.status.replicas}" | grep "ready:1 replicas:1"
2024-07-18 05:39:00,693 INFO    [loop_until]: (max_time=900, interval=30, expected_rc=[0]
2024-07-18 05:39:00,991 INFO    [loop_until]: Function succeeded after 0s (rc=0) - expected pattern found
2024-07-18 05:39:00,991 INFO    [loop_until]: OK (rc = 0)
2024-07-18 05:39:00,991 DEBUG   --- stdout ---
2024-07-18 05:39:00,991 DEBUG   ready:1 replicas:1
2024-07-18 05:39:00,991 DEBUG   --- stderr ---
2024-07-18 05:39:00,991 DEBUG   
2024-07-18 05:39:00,991 INFO    Component lodemon is alive
2024-07-18 05:39:01,850 INFO    Dumping pod description and logs to /mnt/disks/data/xslou/lodestar-fork/results/pyrock/pod-logs/20240718_053900-after-lodemon-deploy/lodemon-77dfcdbb7d-vhzq5.txt
2024-07-18 05:39:01,851 INFO    Dumping pod description and logs to /mnt/disks/data/xslou/lodestar-fork/results/pyrock/pod-logs/20240718_053900-after-lodemon-deploy/lodemon-77dfcdbb7d-vhzq5.txt
2024-07-18 05:39:01,851 INFO    Check pod logs for errors
2024-07-18 05:39:01,852 INFO    
2024-07-18 05:39:01,852 INFO    [loop_until]: kubectl --namespace=xlou --context=gke_engineeringpit_us-east1-d_xlou-cdm exec lodemon-77dfcdbb7d-vhzq5 -- curl --fail --silent --show-error http://localhost:8080/monitoring/start
2024-07-18 05:39:01,852 INFO    [loop_until]: (max_time=180, interval=5, expected_rc=[0]
2024-07-18 05:39:02,604 INFO    [loop_until]: OK (rc = 0)
2024-07-18 05:39:02,605 DEBUG   --- stdout ---
2024-07-18 05:39:02,605 DEBUG   {"Status": "OK", "Message": "Monitoring has been started"}
2024-07-18 05:39:02,605 DEBUG   --- stderr ---
2024-07-18 05:39:02,605 DEBUG   
2024-07-18 05:39:03,430 INFO    Dumping pod description and logs to /mnt/disks/data/xslou/lodestar-fork/results/pyrock/benchmark/pod-logs/stack/after-lodemon-deployment/lodemon-77dfcdbb7d-vhzq5.txt
2024-07-18 05:39:03,430 INFO    Dumping pod description and logs to /mnt/disks/data/xslou/lodestar-fork/results/pyrock/benchmark/pod-logs/stack/after-lodemon-deployment/lodemon-77dfcdbb7d-vhzq5.txt
2024-07-18 05:39:03,431 INFO    Check pod logs for errors
________________________________________________________________________________

[2024-07-18 05:39:03] Monitoring_start post : Post method
________________________________________________________________________________

Setting result to PASS
Task has been successfully stopped