[02/04 20:31:50] pbsdev@pbsdev-centos7-mky18-server:~ 55% time sudo $CV2_PTL_INSTALL_DIR/bin/pbs_benchpress --db-name $CV2_PBS_BUILD_DIR/test/tests/ptl_test_results.json -f $CV2_PTL_INSTALL_DIR/tests/functional/pbs_hook_modifyvnode_state_changes.py -t TestPbsModifyvnodeStateChanges.test_hook_state_changes_02 -p "moms=mom1:mom2"
2021-02-04 20:32:15,852 INFO     input command: pbs_benchpress --db-name /home/pbsdev/pbs/build/test/tests/ptl_test_results.json -f /opt/ptl/tests/functional/pbs_hook_modifyvnode_state_changes.py -t TestPbsModifyvnodeStateChanges.test_hook_state_changes_02 -p moms=mom1:mom2
2021-02-04 20:32:15,852 INFO     param: moms=mom1:mom2
2021-02-04 20:32:15,852 INFO     ptl version: 19.1.1.1093.g7f30851.modified
2021-02-04 20:32:15,856 INFO     platform: Linux pbsdev-centos7-mky18-server 4.19.121-linuxkit #1 SMP Tue Dec 1 17:50:32 UTC 2020 x86_64 x86_64
2021-02-04 20:32:15,856 INFO     python version: 3.6.8
2021-02-04 20:32:15,856 INFO     user: root
2021-02-04 20:32:15,856 INFO     --------------------------------------------------------------------------------
2021-02-04 20:32:15,856 INFO     Cleaning up temporary files
2021-02-04 20:32:15,857 INFO     Cleaning up /tmp dir
2021-02-04 20:32:15,858 INFO     Cleaning up /var/tmp dir
2021-02-04 20:32:15,869 INFO     ======================================================================
2021-02-04 20:32:15,869 INFO     suite name: TestPbsModifyvnodeStateChanges
2021-02-04 20:32:15,869 INFO     suite docstring:

    Test the modifyvnode hook by inducing various vnode state changes and
    inspecting the pbs log for expected values.


2021-02-04 20:32:15,869 INFO     ======================================================================
2021-02-04 20:32:15,869 INFO     ==================================================
2021-02-04 20:32:15,869 INFO      Entered TestPbsModifyvnodeStateChanges setUpClass
2021-02-04 20:32:15,869 INFO     ==================================================
2021-02-04 20:32:15,870 INFOCLI2 pbsdev-centos7-mky18-server: id pbsuser
2021-02-04 20:32:15,873 INFOCLI2 pbsdev-centos7-mky18-server: id pbsuser1
2021-02-04 20:32:15,877 INFOCLI2 pbsdev-centos7-mky18-server: id pbsuser2
2021-02-04 20:32:15,880 INFOCLI2 pbsdev-centos7-mky18-server: id pbsuser3
2021-02-04 20:32:15,883 INFOCLI2 pbsdev-centos7-mky18-server: id pbsuser4
2021-02-04 20:32:15,887 INFOCLI2 pbsdev-centos7-mky18-server: id pbsuser5
2021-02-04 20:32:15,890 INFOCLI2 pbsdev-centos7-mky18-server: id pbsuser6
2021-02-04 20:32:15,892 INFOCLI2 pbsdev-centos7-mky18-server: id pbsuser7
2021-02-04 20:32:15,895 INFOCLI2 pbsdev-centos7-mky18-server: id pbsother
2021-02-04 20:32:15,898 INFOCLI2 pbsdev-centos7-mky18-server: id pbstest
2021-02-04 20:32:15,901 INFOCLI2 pbsdev-centos7-mky18-server: id tstusr00
2021-02-04 20:32:15,904 INFOCLI2 pbsdev-centos7-mky18-server: id tstusr01
2021-02-04 20:32:15,907 INFOCLI2 pbsdev-centos7-mky18-server: id pbsoper
2021-02-04 20:32:15,910 INFOCLI2 pbsdev-centos7-mky18-server: id pbsmgr
2021-02-04 20:32:15,913 INFOCLI2 pbsdev-centos7-mky18-server: id pbsadmin
2021-02-04 20:32:15,916 INFOCLI2 pbsdev-centos7-mky18-server: id pbsdata
2021-02-04 20:32:15,918 INFOCLI2 pbsdev-centos7-mky18-server: id pbsroot
2021-02-04 20:32:15,921 INFOCLI2 pbsdev-centos7-mky18-server: id root
2021-02-04 20:32:15,923 INFOCLI2 pbsdev-centos7-mky18-server: id pbsbuild
2021-02-04 20:32:15,925 INFOCLI2 pbsdev-centos7-mky18-server: id root
2021-02-04 20:32:15,928 INFO     FQDN name pbsdev-centos7-mky18-server.pbsdev-centos7-mky18.local differs from name provided pbsdev-centos7-mky18-server
2021-02-04 20:32:15,938 INFO     server pbsdev-centos7-mky18-server: server operating mode set to cli
2021-02-04 20:32:15,938 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/qstat -Bf pbsdev-centos7-mky18-server.pbsdev-centos7-mky18.local
2021-02-04 20:32:15,947 INFO     server pbsdev-centos7-mky18-server: version 19.1.1.1093.g7f30851.modified
2021-02-04 20:32:15,948 INFO     expect action: created new action kicksched
2021-02-04 20:32:15,948 INFO     expect action: added action kicksched to server pbsdev-centos7-mky18-server
2021-02-04 20:32:15,948 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/qstat -Bf pbsdev-centos7-mky18-server.pbsdev-centos7-mky18.local
2021-02-04 20:32:16,165 INFO     FQDN name pbsdev-centos7-mky18-server.pbsdev-centos7-mky18.local differs from name provided pbsdev-centos7-mky18-server
2021-02-04 20:32:16,170 INFOCLI2 pbsdev-centos7-mky18-server: which chown
2021-02-04 20:32:16,173 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H /usr/bin/chown -R root /var/spool/pbs/sched_priv
2021-02-04 20:32:16,183 INFO     scheduler pbsdev-centos7-mky18-server:  setting dedicated time file to /var/spool/pbs/sched_priv/dedicated_time
2021-02-04 20:32:16,195 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H /opt/pbs/sbin/pbsfs
2021-02-04 20:32:16,210 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H /usr/bin/cat /var/spool/pbs/sched_priv/resource_group
2021-02-04 20:32:16,222 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H /usr/bin/cat /var/spool/pbs/sched_priv/holidays
2021-02-04 20:32:16,233 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H /usr/bin/chown -R root /var/spool/pbs/sched_logs
2021-02-04 20:32:16,243 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/qmgr -c list sched default
2021-02-04 20:32:16,258 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H /usr/bin/chown -R root /var/spool/pbs/sched_priv
2021-02-04 20:32:16,268 INFO     scheduler pbsdev-centos7-mky18-server:  setting dedicated time file to /var/spool/pbs/sched_priv/dedicated_time
2021-02-04 20:32:16,279 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H /opt/pbs/sbin/pbsfs
2021-02-04 20:32:16,296 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H /usr/bin/cat /var/spool/pbs/sched_priv/resource_group
2021-02-04 20:32:16,306 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H /usr/bin/cat /var/spool/pbs/sched_priv/holidays
2021-02-04 20:32:16,317 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H /usr/bin/chown -R root /var/spool/pbs/sched_logs
2021-02-04 20:32:16,329 INFO     FQDN name pbsdev-centos7-mky18-mom1.pbsdev-centos7-mky18.local differs from name provided mom1
2021-02-04 20:32:16,330 INFOCLI2 mom1: ssh mom1 ls -1 /opt/pbs/python/bin/python
2021-02-04 20:32:16,348 INFOCLI2 mom1: ssh mom1 python3 -c "import os;print(os.environ.get("PBS_CONF_FILE", False))"
2021-02-04 20:32:16,434 INFO     FQDN name pbsdev-centos7-mky18-mom2.pbsdev-centos7-mky18.local differs from name provided mom2
2021-02-04 20:32:16,435 INFOCLI2 mom2: ssh mom2 ls -1 /opt/pbs/python/bin/python
2021-02-04 20:32:16,455 INFOCLI2 mom2: ssh mom2 python3 -c "import os;print(os.environ.get("PBS_CONF_FILE", False))"
2021-02-04 20:32:16,537 INFO     FQDN name pbsdev-centos7-mky18-server.pbsdev-centos7-mky18.local differs from name provided pbsdev-centos7-mky18-server
2021-02-04 20:32:16,542 INFO     manager on pbsdev-centos7-mky18-server: set server {'pbs_license_min': 2}
2021-02-04 20:32:16,542 INFOCLI  pbsdev-centos7-mky18-server: sudo -H /opt/pbs/bin/qmgr -c set server pbs_license_min=2
2021-02-04 20:32:16,562 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/qstat -Bf pbsdev-centos7-mky18-server.pbsdev-centos7-mky18.local
2021-02-04 20:32:16,778 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H ls -l /opt/pbs/libexec/pbs_init.d
2021-02-04 20:32:16,790 INFO     running init script to stop pbs server on pbsdev-centos7-mky18-server.pbsdev-centos7-mky18.local using /etc/pbs.conf init_cmd=['sudo', '-H', 'PBS_START_SERVER=1', 'PBS_START_MOM=0', 'PBS_START_SCHED=0', 'PBS_START_COMM=0', '/opt/pbs/libexec/pbs_init.d', 'stop']
2021-02-04 20:32:16,790 INFOCLI2 pbsdev-centos7-mky18-server: /tmp/PtlPbsgcb056tq
Contents of /tmp/PtlPbsgcb056tq:
----------------------------------------
#!/bin/bash
sudo -H PBS_START_SERVER=1 PBS_START_MOM=0 PBS_START_SCHED=0 PBS_START_COMM=0 /opt/pbs/libexec/pbs_init.d stop
----------------------------------------
2021-02-04 20:32:22,380 INFOCLI2 pbsdev-centos7-mky18-server: which rm
2021-02-04 20:32:22,383 INFOCLI2 pbsdev-centos7-mky18-server: /usr/bin/rm /tmp/PtlPbsgcb056tq
2021-02-04 20:32:22,387 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H ls -l /opt/pbs/libexec/pbs_init.d
2021-02-04 20:32:22,397 INFO     running init script to start pbs server on pbsdev-centos7-mky18-server.pbsdev-centos7-mky18.local using /etc/pbs.conf init_cmd=['sudo', '-H', 'PBS_START_SERVER=1', 'PBS_START_MOM=0', 'PBS_START_SCHED=0', 'PBS_START_COMM=0', '/opt/pbs/libexec/pbs_init.d', 'start']
2021-02-04 20:32:22,398 INFOCLI2 pbsdev-centos7-mky18-server: /tmp/PtlPbs4hd2glh6
Contents of /tmp/PtlPbs4hd2glh6:
----------------------------------------
#!/bin/bash
sudo -H PBS_START_SERVER=1 PBS_START_MOM=0 PBS_START_SCHED=0 PBS_START_COMM=0 /opt/pbs/libexec/pbs_init.d start
----------------------------------------
2021-02-04 20:32:26,408 INFOCLI2 pbsdev-centos7-mky18-server: /usr/bin/rm /tmp/PtlPbs4hd2glh6
2021-02-04 20:32:26,415 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H /usr/bin/cat /var/spool/pbs/server_priv/server.lock
2021-02-04 20:32:26,425 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/qstat -Bf pbsdev-centos7-mky18-server.pbsdev-centos7-mky18.local
2021-02-04 20:32:26,435 INFO     ===================================================
2021-02-04 20:32:26,435 INFO     Completed TestPbsModifyvnodeStateChanges setUpClass
2021-02-04 20:32:26,435 INFO     ===================================================
2021-02-04 20:32:26,467 INFO     mom pbsdev-centos7-mky18-mom1 log match: searching for "alps_client" - with existence - No match
2021-02-04 20:32:26,969 INFOCLI2 pbsdev-centos7-mky18-mom1: ssh pbsdev-centos7-mky18-mom1.pbsdev-centos7-mky18.local ls -l /etc/sgi-compute-node-release
2021-02-04 20:32:26,987 INFOCLI2 pbsdev-centos7-mky18-mom1: ssh pbsdev-centos7-mky18-mom1.pbsdev-centos7-mky18.local ls -l /etc/sgi-known-distributions
2021-02-04 20:32:27,005 INFOCLI2 pbsdev-centos7-mky18-mom2: ssh pbsdev-centos7-mky18-mom2.pbsdev-centos7-mky18.local ls -l /etc/sgi-compute-node-release
2021-02-04 20:32:27,022 INFOCLI2 pbsdev-centos7-mky18-mom2: ssh pbsdev-centos7-mky18-mom2.pbsdev-centos7-mky18.local ls -l /etc/sgi-known-distributions
2021-02-04 20:32:27,040 INFOCLI2 mom1: ssh mom1 which cat
2021-02-04 20:32:27,059 INFOCLI2 mom1: ssh mom1 /usr/bin/cat /proc/meminfo
2021-02-04 20:32:27,091 INFOCLI2 mom1: ssh mom1 df -k /var/spool/pbs
2021-02-04 20:32:27,125 INFOCLI2 grep'ing for mom_priv in /var/spool/pbs
2021-02-04 20:32:27,125 INFOCLI2 mom1: ssh mom1 ls -l /var/spool/pbs
2021-02-04 20:32:27,142 INFOCLI2 mom1: ssh mom1 sudo -H ls /var/spool/pbs/mom_priv
2021-02-04 20:32:27,171 INFOCLI2 grep'ing for server_priv in /var/spool/pbs
2021-02-04 20:32:27,171 INFOCLI2 mom1: ssh mom1 ls -l /var/spool/pbs
2021-02-04 20:32:27,189 INFOCLI2 mom1: ssh mom1 sudo -H ls /var/spool/pbs/server_priv
2021-02-04 20:32:27,215 INFOCLI2 grep'ing for sched_priv in /var/spool/pbs
2021-02-04 20:32:27,215 INFOCLI2 mom1: ssh mom1 ls -l /var/spool/pbs
2021-02-04 20:32:27,232 INFOCLI2 mom1: ssh mom1 sudo -H ls /var/spool/pbs/sched_priv
2021-02-04 20:32:27,257 INFOCLI2 mom1: ssh mom1 sudo -H -u pbsuser ls /home/pbsuser
2021-02-04 20:32:27,282 INFOCLI2 mom1: ssh mom1 sudo -H -u pbsuser1 ls /home/pbsuser1
2021-02-04 20:32:27,307 INFOCLI2 mom1: ssh mom1 sudo -H -u pbsuser2 ls /home/pbsuser2
2021-02-04 20:32:27,332 INFOCLI2 mom1: ssh mom1 sudo -H -u pbsuser3 ls /home/pbsuser3
2021-02-04 20:32:27,357 INFOCLI2 mom1: ssh mom1 sudo -H -u pbsuser4 ls /home/pbsuser4
2021-02-04 20:32:27,382 INFOCLI2 mom1: ssh mom1 sudo -H -u pbsuser5 ls /home/pbsuser5
2021-02-04 20:32:27,407 INFOCLI2 mom1: ssh mom1 sudo -H -u pbsuser6 ls /home/pbsuser6
2021-02-04 20:32:27,432 INFOCLI2 mom1: ssh mom1 sudo -H -u pbsuser7 ls /home/pbsuser7
2021-02-04 20:32:27,457 INFOCLI2 mom1: ssh mom1 sudo -H -u pbsother ls /home/pbsother
2021-02-04 20:32:27,482 INFOCLI2 mom1: ssh mom1 sudo -H -u pbstest ls /home/pbstest
2021-02-04 20:32:27,507 INFOCLI2 mom1: ssh mom1 sudo -H -u tstusr00 ls /home/tstusr00
2021-02-04 20:32:27,531 INFOCLI2 mom1: ssh mom1 sudo -H -u tstusr01 ls /home/tstusr01
2021-02-04 20:32:27,556 INFOCLI2 mom1: ssh mom1 sudo -H -u pbsoper ls /home/pbsoper
2021-02-04 20:32:27,582 INFOCLI2 mom1: ssh mom1 sudo -H -u pbsmgr ls /home/pbsmgr
2021-02-04 20:32:27,607 INFOCLI2 mom1: ssh mom1 sudo -H -u pbsadmin ls /home/pbsadmin
2021-02-04 20:32:27,632 INFOCLI2 mom1: ssh mom1 sudo -H -u pbsdata ls /home/pbsdata
2021-02-04 20:32:27,658 INFOCLI2 mom1: ssh mom1 sudo -H -u pbsroot ls /home/pbsroot
2021-02-04 20:32:27,683 INFOCLI2 mom1: ssh mom1 sudo -H -u root ls /root
2021-02-04 20:32:27,709 INFOCLI2 mom1: ssh mom1 sudo -H -u pbsbuild ls /home/pbsbuild
2021-02-04 20:32:27,734 INFOCLI2 mom1: ssh mom1 sudo -H -u root ls /root
2021-02-04 20:32:27,760 INFOCLI2 pbsdev-centos7-mky18-server: /usr/bin/cat /proc/meminfo
2021-02-04 20:32:27,763 INFOCLI2 pbsdev-centos7-mky18-server: df -k /var/spool/pbs
2021-02-04 20:32:27,769 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H ls /var/spool/pbs/mom_priv
2021-02-04 20:32:27,779 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H ls /var/spool/pbs/server_priv
2021-02-04 20:32:27,790 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H ls /var/spool/pbs/sched_priv
2021-02-04 20:32:27,801 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H -u pbsuser ls /home/pbsuser
2021-02-04 20:32:27,811 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H -u pbsuser1 ls /home/pbsuser1
2021-02-04 20:32:27,822 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H -u pbsuser2 ls /home/pbsuser2
2021-02-04 20:32:27,833 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H -u pbsuser3 ls /home/pbsuser3
2021-02-04 20:32:27,845 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H -u pbsuser4 ls /home/pbsuser4
2021-02-04 20:32:27,856 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H -u pbsuser5 ls /home/pbsuser5
2021-02-04 20:32:27,867 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H -u pbsuser6 ls /home/pbsuser6
2021-02-04 20:32:27,878 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H -u pbsuser7 ls /home/pbsuser7
2021-02-04 20:32:27,889 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H -u pbsother ls /home/pbsother
2021-02-04 20:32:27,900 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H -u pbstest ls /home/pbstest
2021-02-04 20:32:27,911 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H -u tstusr00 ls /home/tstusr00
2021-02-04 20:32:27,922 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H -u tstusr01 ls /home/tstusr01
2021-02-04 20:32:27,934 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H -u pbsoper ls /home/pbsoper
2021-02-04 20:32:27,945 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H -u pbsmgr ls /home/pbsmgr
2021-02-04 20:32:27,956 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H -u pbsadmin ls /home/pbsadmin
2021-02-04 20:32:27,967 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H -u pbsdata ls /home/pbsdata
2021-02-04 20:32:27,979 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H -u pbsroot ls /home/pbsroot
2021-02-04 20:32:27,990 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H -u root ls /root
2021-02-04 20:32:28,001 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H -u pbsbuild ls /home/pbsbuild
2021-02-04 20:32:28,013 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H -u root ls /root
2021-02-04 20:32:28,024 INFOCLI2 mom2: ssh mom2 which cat
2021-02-04 20:32:28,042 INFOCLI2 mom2: ssh mom2 /usr/bin/cat /proc/meminfo
2021-02-04 20:32:28,077 INFOCLI2 mom2: ssh mom2 df -k /var/spool/pbs
2021-02-04 20:32:28,111 INFOCLI2 grep'ing for mom_priv in /var/spool/pbs
2021-02-04 20:32:28,111 INFOCLI2 mom2: ssh mom2 ls -l /var/spool/pbs
2021-02-04 20:32:28,129 INFOCLI2 mom2: ssh mom2 sudo -H ls /var/spool/pbs/mom_priv
2021-02-04 20:32:28,154 INFOCLI2 grep'ing for server_priv in /var/spool/pbs
2021-02-04 20:32:28,154 INFOCLI2 mom2: ssh mom2 ls -l /var/spool/pbs
2021-02-04 20:32:28,172 INFOCLI2 mom2: ssh mom2 sudo -H ls /var/spool/pbs/server_priv
2021-02-04 20:32:28,198 INFOCLI2 grep'ing for sched_priv in /var/spool/pbs
2021-02-04 20:32:28,198 INFOCLI2 mom2: ssh mom2 ls -l /var/spool/pbs
2021-02-04 20:32:28,216 INFOCLI2 mom2: ssh mom2 sudo -H ls /var/spool/pbs/sched_priv
2021-02-04 20:32:28,241 INFOCLI2 mom2: ssh mom2 sudo -H -u pbsuser ls /home/pbsuser
2021-02-04 20:32:28,266 INFOCLI2 mom2: ssh mom2 sudo -H -u pbsuser1 ls /home/pbsuser1
2021-02-04 20:32:28,294 INFOCLI2 mom2: ssh mom2 sudo -H -u pbsuser2 ls /home/pbsuser2
2021-02-04 20:32:28,320 INFOCLI2 mom2: ssh mom2 sudo -H -u pbsuser3 ls /home/pbsuser3
2021-02-04 20:32:28,347 INFOCLI2 mom2: ssh mom2 sudo -H -u pbsuser4 ls /home/pbsuser4
2021-02-04 20:32:28,370 INFOCLI2 mom2: ssh mom2 sudo -H -u pbsuser5 ls /home/pbsuser5
2021-02-04 20:32:28,397 INFOCLI2 mom2: ssh mom2 sudo -H -u pbsuser6 ls /home/pbsuser6
2021-02-04 20:32:28,421 INFOCLI2 mom2: ssh mom2 sudo -H -u pbsuser7 ls /home/pbsuser7
2021-02-04 20:32:28,449 INFOCLI2 mom2: ssh mom2 sudo -H -u pbsother ls /home/pbsother
2021-02-04 20:32:28,477 INFOCLI2 mom2: ssh mom2 sudo -H -u pbstest ls /home/pbstest
2021-02-04 20:32:28,506 INFOCLI2 mom2: ssh mom2 sudo -H -u tstusr00 ls /home/tstusr00
2021-02-04 20:32:28,535 INFOCLI2 mom2: ssh mom2 sudo -H -u tstusr01 ls /home/tstusr01
2021-02-04 20:32:28,561 INFOCLI2 mom2: ssh mom2 sudo -H -u pbsoper ls /home/pbsoper
2021-02-04 20:32:28,589 INFOCLI2 mom2: ssh mom2 sudo -H -u pbsmgr ls /home/pbsmgr
2021-02-04 20:32:28,618 INFOCLI2 mom2: ssh mom2 sudo -H -u pbsadmin ls /home/pbsadmin
2021-02-04 20:32:28,645 INFOCLI2 mom2: ssh mom2 sudo -H -u pbsdata ls /home/pbsdata
2021-02-04 20:32:28,669 INFOCLI2 mom2: ssh mom2 sudo -H -u pbsroot ls /home/pbsroot
2021-02-04 20:32:28,697 INFOCLI2 mom2: ssh mom2 sudo -H -u root ls /root
2021-02-04 20:32:28,724 INFOCLI2 mom2: ssh mom2 sudo -H -u pbsbuild ls /home/pbsbuild
2021-02-04 20:32:28,749 INFOCLI2 mom2: ssh mom2 sudo -H -u root ls /root
2021-02-04 20:32:28,776 INFO     test name: test_hook_state_changes_02 (tests.functional.pbs_hook_modifyvnode_state_changes.TestPbsModifyvnodeStateChanges)...
2021-02-04 20:32:28,776 INFO     test start time: Thu Feb  4 20:32:28 2021
2021-02-04 20:32:28,776 INFO     test docstring:

        Test:  stop and start the pbs server; look for proper log messages

2021-02-04 20:32:28,777 INFO     =============================================
2021-02-04 20:32:28,777 INFO      Entered TestPbsModifyvnodeStateChanges setUp
2021-02-04 20:32:28,777 INFO     =============================================
2021-02-04 20:32:28,777 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/qstat -Bf pbsdev-centos7-mky18-server.pbsdev-centos7-mky18.local
2021-02-04 20:32:28,787 INFO     status on pbsdev-centos7-mky18-server: server
2021-02-04 20:32:28,787 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/qstat -Bf pbsdev-centos7-mky18-server.pbsdev-centos7-mky18.local
2021-02-04 20:32:29,001 INFO     manager on pbsdev-centos7-mky18-server: unset server managers
2021-02-04 20:32:29,001 INFOCLI  pbsdev-centos7-mky18-server: sudo -H /opt/pbs/bin/qmgr -c unset server managers
2021-02-04 20:32:29,021 INFO     manager on pbsdev-centos7-mky18-server: unset server operators
2021-02-04 20:32:29,021 INFOCLI  pbsdev-centos7-mky18-server: sudo -H /opt/pbs/bin/qmgr -c unset server operators
2021-02-04 20:32:29,040 INFO     status on pbsdev-centos7-mky18-server: server ['managers', 'operators']
2021-02-04 20:32:29,040 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/qstat -Bf pbsdev-centos7-mky18-server.pbsdev-centos7-mky18.local
2021-02-04 20:32:29,049 INFO     manager on pbsdev-centos7-mky18-server: set server {'managers': (2, 'root@*,pbsmgr@*'), 'operators': (2, 'pbsoper@*')}
2021-02-04 20:32:29,050 INFOCLI  pbsdev-centos7-mky18-server: sudo -H /opt/pbs/bin/qmgr -c set server managers+="root@*,pbsmgr@*",operators+=pbsoper@*
2021-02-04 20:32:29,068 INFO     server pbsdev-centos7-mky18-server: reverting configuration to defaults
2021-02-04 20:32:29,069 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/qstat -Bf pbsdev-centos7-mky18-server.pbsdev-centos7-mky18.local
2021-02-04 20:32:29,283 INFO     status on pbsdev-centos7-mky18-server: job
2021-02-04 20:32:29,283 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/qstat -f @pbsdev-centos7-mky18-server.pbsdev-centos7-mky18.local
2021-02-04 20:32:29,496 INFO     status on pbsdev-centos7-mky18-server: sched
2021-02-04 20:32:29,497 INFO     manager on pbsdev-centos7-mky18-server: list sched
2021-02-04 20:32:29,497 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/qmgr -c list sched
2021-02-04 20:32:29,506 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H /usr/bin/chown -R root /var/spool/pbs/sched_priv
2021-02-04 20:32:29,520 INFO     scheduler pbsdev-centos7-mky18-server:  setting dedicated time file to /var/spool/pbs/sched_priv/dedicated_time
2021-02-04 20:32:29,531 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H /opt/pbs/sbin/pbsfs
2021-02-04 20:32:29,546 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H /usr/bin/cat /var/spool/pbs/sched_priv/resource_group
2021-02-04 20:32:29,557 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H /usr/bin/cat /var/spool/pbs/sched_priv/holidays
2021-02-04 20:32:29,568 INFO     manager on pbsdev-centos7-mky18-server as root: set sched default {'scheduling': 'False'}
2021-02-04 20:32:29,568 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/qmgr -c set sched default scheduling=False
2021-02-04 20:32:29,581 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/qmgr -c list sched default
2021-02-04 20:32:29,591 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H /usr/bin/chown -R root /var/spool/pbs/sched_priv
2021-02-04 20:32:29,601 INFO     scheduler pbsdev-centos7-mky18-server:  setting dedicated time file to /var/spool/pbs/sched_priv/dedicated_time
2021-02-04 20:32:29,612 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H /opt/pbs/sbin/pbsfs
2021-02-04 20:32:29,629 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H /usr/bin/cat /var/spool/pbs/sched_priv/resource_group
2021-02-04 20:32:29,641 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H /usr/bin/cat /var/spool/pbs/sched_priv/holidays
2021-02-04 20:32:29,651 INFO     expect on server pbsdev-centos7-mky18-server: state != scheduling sched default ...  OK
2021-02-04 20:32:29,652 INFO     delete job on pbsdev-centos7-mky18-server as root:
2021-02-04 20:32:29,652 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/qstat -f @pbsdev-centos7-mky18-server.pbsdev-centos7-mky18.local
2021-02-04 20:32:29,869 INFO     expect on server pbsdev-centos7-mky18-server: job_state set 0 job ...  OK
2021-02-04 20:32:29,870 INFO     manager on pbsdev-centos7-mky18-server as root: set sched default {'scheduling': 'True'}
2021-02-04 20:32:29,870 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/qmgr -c set sched default scheduling=True
2021-02-04 20:32:29,882 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/qmgr -c list sched default
2021-02-04 20:32:29,891 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H /usr/bin/chown -R root /var/spool/pbs/sched_priv
2021-02-04 20:32:29,902 INFO     scheduler pbsdev-centos7-mky18-server:  setting dedicated time file to /var/spool/pbs/sched_priv/dedicated_time
2021-02-04 20:32:29,912 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H /opt/pbs/sbin/pbsfs
2021-02-04 20:32:29,929 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H /usr/bin/cat /var/spool/pbs/sched_priv/resource_group
2021-02-04 20:32:29,939 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H /usr/bin/cat /var/spool/pbs/sched_priv/holidays
2021-02-04 20:32:29,950 INFO     expect on server pbsdev-centos7-mky18-server: scheduling = True sched default ...  OK
2021-02-04 20:32:29,950 INFO     status on pbsdev-centos7-mky18-server as root: reservation
2021-02-04 20:32:29,950 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/pbs_rstat -f
2021-02-04 20:32:29,961 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/qstat -Bf pbsdev-centos7-mky18-server.pbsdev-centos7-mky18.local
2021-02-04 20:32:30,177 INFO     status on pbsdev-centos7-mky18-server: job
2021-02-04 20:32:30,177 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/qstat -f @pbsdev-centos7-mky18-server.pbsdev-centos7-mky18.local
2021-02-04 20:32:30,396 INFO     status on pbsdev-centos7-mky18-server: sched
2021-02-04 20:32:30,396 INFO     manager on pbsdev-centos7-mky18-server: list sched
2021-02-04 20:32:30,396 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/qmgr -c list sched
2021-02-04 20:32:30,408 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H /usr/bin/chown -R root /var/spool/pbs/sched_priv
2021-02-04 20:32:30,419 INFO     scheduler pbsdev-centos7-mky18-server:  setting dedicated time file to /var/spool/pbs/sched_priv/dedicated_time
2021-02-04 20:32:30,430 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H /opt/pbs/sbin/pbsfs
2021-02-04 20:32:30,446 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H /usr/bin/cat /var/spool/pbs/sched_priv/resource_group
2021-02-04 20:32:30,457 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H /usr/bin/cat /var/spool/pbs/sched_priv/holidays
2021-02-04 20:32:30,468 INFO     manager on pbsdev-centos7-mky18-server as root: set sched default {'scheduling': 'False'}
2021-02-04 20:32:30,468 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/qmgr -c set sched default scheduling=False
2021-02-04 20:32:30,480 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/qmgr -c list sched default
2021-02-04 20:32:30,491 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H /usr/bin/chown -R root /var/spool/pbs/sched_priv
2021-02-04 20:32:30,502 INFO     scheduler pbsdev-centos7-mky18-server:  setting dedicated time file to /var/spool/pbs/sched_priv/dedicated_time
2021-02-04 20:32:30,512 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H /opt/pbs/sbin/pbsfs
2021-02-04 20:32:30,529 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H /usr/bin/cat /var/spool/pbs/sched_priv/resource_group
2021-02-04 20:32:30,540 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H /usr/bin/cat /var/spool/pbs/sched_priv/holidays
2021-02-04 20:32:30,551 INFO     expect on server pbsdev-centos7-mky18-server: state != scheduling sched default ...  OK
2021-02-04 20:32:30,551 INFO     delete job on pbsdev-centos7-mky18-server as root:
2021-02-04 20:32:30,552 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/qstat -f @pbsdev-centos7-mky18-server.pbsdev-centos7-mky18.local
2021-02-04 20:32:30,768 INFO     expect on server pbsdev-centos7-mky18-server: job_state set 0 job ...  OK
2021-02-04 20:32:30,769 INFO     manager on pbsdev-centos7-mky18-server as root: set sched default {'scheduling': 'True'}
2021-02-04 20:32:30,769 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/qmgr -c set sched default scheduling=True
2021-02-04 20:32:30,781 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/qmgr -c list sched default
2021-02-04 20:32:30,791 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H /usr/bin/chown -R root /var/spool/pbs/sched_priv
2021-02-04 20:32:30,800 INFO     scheduler pbsdev-centos7-mky18-server:  setting dedicated time file to /var/spool/pbs/sched_priv/dedicated_time
2021-02-04 20:32:30,811 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H /opt/pbs/sbin/pbsfs
2021-02-04 20:32:30,826 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H /usr/bin/cat /var/spool/pbs/sched_priv/resource_group
2021-02-04 20:32:30,836 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H /usr/bin/cat /var/spool/pbs/sched_priv/holidays
2021-02-04 20:32:30,847 INFO     expect on server pbsdev-centos7-mky18-server: scheduling = True sched default ...  OK
2021-02-04 20:32:30,847 INFO     status on pbsdev-centos7-mky18-server as root: reservation
2021-02-04 20:32:30,847 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/pbs_rstat -f
2021-02-04 20:32:30,857 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/qstat -Bf pbsdev-centos7-mky18-server.pbsdev-centos7-mky18.local
2021-02-04 20:32:31,075 INFO     manager on pbsdev-centos7-mky18-server: unset server ['scheduling', 'log_events', 'mailer', 'mail_from', 'query_other_jobs', 'resources_default.ncpus', 'scheduler_iteration', 'resv_enable', 'max_array_size', 'pbs_license_max', 'pbs_license_linger_time', 'eligible_time_enable', 'max_concurrent_provision', 'sync_mom_hookfiles_timeout', 'max_job_sequence_id']
2021-02-04 20:32:31,076 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/qmgr -c unset server scheduling,log_events,mailer,mail_from,query_other_jobs,resources_default.ncpus,scheduler_iteration,resv_enable,max_array_size,pbs_license_max,pbs_license_linger_time,eligible_time_enable,max_concurrent_provision,sync_mom_hookfiles_timeout,max_job_sequence_id
2021-02-04 20:32:31,090 INFOCLI  pbsdev-centos7-mky18-server: sudo -H /opt/pbs/bin/qmgr -c list hook
2021-02-04 20:32:31,108 INFO     manager on pbsdev-centos7-mky18-server: delete hook p1234
2021-02-04 20:32:31,108 INFOCLI  pbsdev-centos7-mky18-server: sudo -H /opt/pbs/bin/qmgr -c delete hook p1234
2021-02-04 20:32:31,125 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/qstat -Qf @pbsdev-centos7-mky18-server.pbsdev-centos7-mky18.local
2021-02-04 20:32:31,341 INFO     status on pbsdev-centos7-mky18-server: node
2021-02-04 20:32:31,342 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/pbsnodes -s pbsdev-centos7-mky18-server.pbsdev-centos7-mky18.local -v -a
2021-02-04 20:32:31,355 INFO     manager on pbsdev-centos7-mky18-server: delete queue workq
2021-02-04 20:32:31,355 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/qmgr -c delete queue workq
2021-02-04 20:32:31,366 INFO     manager on pbsdev-centos7-mky18-server: create queue workq {'queue_type': 'Execution', 'enabled': 'True', 'started': 'True'}
2021-02-04 20:32:31,366 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/qmgr -c create queue workq queue_type=Execution,enabled=True,started=True
2021-02-04 20:32:31,377 INFO     status on pbsdev-centos7-mky18-server: queue workq
2021-02-04 20:32:31,377 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/qstat -Qf workq@pbsdev-centos7-mky18-server.pbsdev-centos7-mky18.local
2021-02-04 20:32:31,590 INFO     manager on pbsdev-centos7-mky18-server: list sched
2021-02-04 20:32:31,591 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/qmgr -c list sched
2021-02-04 20:32:31,602 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H /usr/bin/chown -R root /var/spool/pbs/sched_priv
2021-02-04 20:32:31,612 INFO     scheduler pbsdev-centos7-mky18-server:  setting dedicated time file to /var/spool/pbs/sched_priv/dedicated_time
2021-02-04 20:32:31,622 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H /opt/pbs/sbin/pbsfs
2021-02-04 20:32:31,637 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H /usr/bin/cat /var/spool/pbs/sched_priv/resource_group
2021-02-04 20:32:31,649 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H /usr/bin/cat /var/spool/pbs/sched_priv/holidays
2021-02-04 20:32:31,659 INFO     manager on pbsdev-centos7-mky18-server: delete node @default
2021-02-04 20:32:31,659 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/qmgr -c delete node @default
2021-02-04 20:32:31,671 INFOCLI  pbsdev-centos7-mky18-server: sudo -H /opt/pbs/bin/qmgr -c list hook
2021-02-04 20:32:31,690 INFO     manager on pbsdev-centos7-mky18-server: set hook pbs_cgroups {'enabled': 'false'}
2021-02-04 20:32:31,691 INFOCLI  pbsdev-centos7-mky18-server: sudo -H /opt/pbs/bin/qmgr -c set hook pbs_cgroups enabled=false
2021-02-04 20:32:31,712 INFO     manager on pbsdev-centos7-mky18-server: set server {'default_queue': 'workq'}
2021-02-04 20:32:31,712 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/qmgr -c set server default_queue=workq
2021-02-04 20:32:31,726 INFO     status on pbsdev-centos7-mky18-server: resource
2021-02-04 20:32:31,726 INFO     manager on pbsdev-centos7-mky18-server: list resource
2021-02-04 20:32:31,726 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/qmgr -c list resource
2021-02-04 20:32:31,736 INFOCLI  status on pbsdev-centos7-mky18-server: server license_count
2021-02-04 20:32:31,736 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/qstat -Bf pbsdev-centos7-mky18-server.pbsdev-centos7-mky18.local
2021-02-04 20:32:31,950 INFO     server: pbsdev-centos7-mky18-server.pbsdev-centos7-mky18.local licensed
2021-02-04 20:32:31,951 INFO     status on pbsdev-centos7-mky18-server: server pbsdev-centos7-mky18-server.pbsdev-centos7-mky18.local
2021-02-04 20:32:31,951 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/qstat -Bf pbsdev-centos7-mky18-server.pbsdev-centos7-mky18.local
2021-02-04 20:32:32,165 INFOCLI2 pbsdev-centos7-mky18-mom1: ssh pbsdev-centos7-mky18-mom1.pbsdev-centos7-mky18.local ls -1 /opt/pbs/python/bin/python
2021-02-04 20:32:32,184 INFOCLI2 pbsdev-centos7-mky18-mom1: ssh pbsdev-centos7-mky18-mom1.pbsdev-centos7-mky18.local python3 -c "import os;print(os.environ.get("PBS_CONF_FILE", False))"
2021-02-04 20:32:32,232 INFOCLI2 pbsdev-centos7-mky18-mom2: ssh pbsdev-centos7-mky18-mom2.pbsdev-centos7-mky18.local ls -1 /opt/pbs/python/bin/python
2021-02-04 20:32:32,249 INFOCLI2 pbsdev-centos7-mky18-mom2: ssh pbsdev-centos7-mky18-mom2.pbsdev-centos7-mky18.local python3 -c "import os;print(os.environ.get("PBS_CONF_FILE", False))"
2021-02-04 20:32:32,298 ERROR    Couldn't revert PBS_DAEMON_SERVICE_USER in pbs.conf to its default value
2021-02-04 20:32:32,303 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H /usr/bin/cat /var/spool/pbs/sched_priv/sched.lock
2021-02-04 20:32:32,314 INFO     scheduler pbsdev-centos7-mky18-server: reverting configuration to defaults
2021-02-04 20:32:32,314 INFO     manager on pbsdev-centos7-mky18-server: unset sched ['sched_cycle_length', 'throughput_mode', 'job_run_wait', 'opt_backfill_fuzzy', 'partition', 'sched_priv', 'sched_log', 'scheduling', 'scheduler_iteration', 'preempt_queue_prio', 'preempt_prio', 'preempt_order', 'preempt_sort', 'log_events', 'server_dyn_res_alarm']
2021-02-04 20:32:32,315 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/qmgr -c unset sched sched_cycle_length,throughput_mode,job_run_wait,opt_backfill_fuzzy,partition,sched_priv,sched_log,scheduling,scheduler_iteration,preempt_queue_prio,preempt_prio,preempt_order,preempt_sort,log_events,server_dyn_res_alarm
2021-02-04 20:32:32,328 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H /usr/bin/cat /var/spool/pbs/sched_priv/dedicated_time
2021-02-04 20:32:32,340 INFOCLI2 pbsdev-centos7-mky18-server: which cp
2021-02-04 20:32:32,343 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H /usr/bin/cp /tmp/PtlPbs9xizgemi /var/spool/pbs/sched_priv/dedicated_time
2021-02-04 20:32:32,353 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H cmp /opt/pbs/etc/pbs_resource_group /var/spool/pbs/sched_priv/resource_group
2021-02-04 20:32:32,364 INFO     scheduler pbsdev-centos7-mky18-server: reverting holidays file to default
2021-02-04 20:32:32,364 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H cmp /opt/pbs/etc/pbs_holidays /var/spool/pbs/sched_priv/holidays
2021-02-04 20:32:32,374 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H cmp /opt/pbs/etc/pbs_sched_config /var/spool/pbs/sched_priv/sched_config
2021-02-04 20:32:32,385 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H cmp /opt/pbs/etc/pbs_dedicated /var/spool/pbs/sched_priv/dedicated_time
2021-02-04 20:32:32,396 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H /usr/bin/cp /opt/pbs/etc/pbs_dedicated /var/spool/pbs/sched_priv/dedicated_time
2021-02-04 20:32:32,406 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H /usr/bin/chown root /var/spool/pbs/sched_priv/dedicated_time
2021-02-04 20:32:32,416 INFO     Scheduler sent signal -HUP
2021-02-04 20:32:32,417 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H /usr/bin/cat /var/spool/pbs/sched_priv/sched.lock
2021-02-04 20:32:32,427 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H kill -HUP 46148
2021-02-04 20:32:32,437 INFOCLI2 pbsdev-centos7-mky18-server: /opt/pbs/sbin/pbsfs -e -I default
2021-02-04 20:32:32,461 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H /usr/bin/cat /var/spool/pbs/sched_priv/sched.lock
2021-02-04 20:32:32,471 INFO     status on pbsdev-centos7-mky18-server: sched default
2021-02-04 20:32:32,471 INFO     manager on pbsdev-centos7-mky18-server: list sched default
2021-02-04 20:32:32,471 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/qmgr -c list sched default
2021-02-04 20:32:32,481 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H /usr/bin/chown -R root /var/spool/pbs/sched_priv
2021-02-04 20:32:32,491 INFO     scheduler pbsdev-centos7-mky18-server:  setting dedicated time file to /var/spool/pbs/sched_priv/dedicated_time
2021-02-04 20:32:32,503 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H /opt/pbs/sbin/pbsfs
2021-02-04 20:32:32,522 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H /usr/bin/cat /var/spool/pbs/sched_priv/resource_group
2021-02-04 20:32:32,533 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H /usr/bin/cat /var/spool/pbs/sched_priv/holidays
2021-02-04 20:32:32,596 INFOCLI2 pbsdev-centos7-mky18-mom1: ssh pbsdev-centos7-mky18-mom1.pbsdev-centos7-mky18.local ls -1 /opt/pbs/python/bin/python
2021-02-04 20:32:32,632 INFOCLI2 pbsdev-centos7-mky18-mom1: ssh pbsdev-centos7-mky18-mom1.pbsdev-centos7-mky18.local /usr/bin/python3 -c "import sys; print(sys.platform)"
2021-02-04 20:32:32,683 INFOCLI2 pbsdev-centos7-mky18-mom1: ssh pbsdev-centos7-mky18-mom1.pbsdev-centos7-mky18.local sudo -H /usr/bin/cat /var/spool/pbs/mom_priv/mom.lock
2021-02-04 20:32:32,708 INFO     status on pbsdev-centos7-mky18-server: node pbsdev-centos7-mky18-mom1
2021-02-04 20:32:32,709 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/pbsnodes -s pbsdev-centos7-mky18-server.pbsdev-centos7-mky18.local -v pbsdev-centos7-mky18-mom1
2021-02-04 20:32:32,718 ERROR    <DshUtils.run_cmd>err: ['/opt/pbs/bin/pbsnodes: Server has no node list']
2021-02-04 20:32:32,718 INFOCLI2 pbsdev-centos7-mky18-mom1: ssh pbsdev-centos7-mky18-mom1.pbsdev-centos7-mky18.local which rm
2021-02-04 20:32:32,737 INFOCLI2 pbsdev-centos7-mky18-mom1: ssh pbsdev-centos7-mky18-mom1.pbsdev-centos7-mky18.local sudo -H /usr/bin/rm -f /var/spool/pbs/mom_priv/epilogue
2021-02-04 20:32:32,763 INFOCLI2 pbsdev-centos7-mky18-mom1: ssh pbsdev-centos7-mky18-mom1.pbsdev-centos7-mky18.local sudo -H /usr/bin/rm -f /var/spool/pbs/mom_priv/prologue
2021-02-04 20:32:32,788 INFOCLI  pbsdev-centos7-mky18-mom1: ssh pbsdev-centos7-mky18-mom1.pbsdev-centos7-mky18.local sudo -H /opt/pbs/sbin/pbs_mom -s list
2021-02-04 20:32:32,882 INFOCLI2 pbsdev-centos7-mky18-mom1: ssh pbsdev-centos7-mky18-mom1.pbsdev-centos7-mky18.local /usr/bin/python3 -c "import tempfile;print(tempfile.mkstemp('PtlPbstmpcopy')[1])"
2021-02-04 20:32:32,934 INFOCLI2 pbsdev-centos7-mky18-mom1: ssh pbsdev-centos7-mky18-mom1.pbsdev-centos7-mky18.local which scp
2021-02-04 20:32:32,951 INFOCLI2 pbsdev-centos7-mky18-server: /usr/bin/scp /tmp/PtlPbsgc1i5d05 pbsdev-centos7-mky18-mom1.pbsdev-centos7-mky18.local:/tmp/tmp84yl78zqPtlPbstmpcopy
2021-02-04 20:32:32,975 INFOCLI2 pbsdev-centos7-mky18-mom1: ssh pbsdev-centos7-mky18-mom1.pbsdev-centos7-mky18.local which cp
2021-02-04 20:32:32,995 INFOCLI2 pbsdev-centos7-mky18-mom1: ssh pbsdev-centos7-mky18-mom1.pbsdev-centos7-mky18.local sudo -H /usr/bin/cp /tmp/tmp84yl78zqPtlPbstmpcopy /var/spool/pbs/mom_priv/config
2021-02-04 20:32:33,021 INFOCLI2 pbsdev-centos7-mky18-mom1: ssh pbsdev-centos7-mky18-mom1.pbsdev-centos7-mky18.local /usr/bin/rm /tmp/tmp84yl78zqPtlPbstmpcopy
2021-02-04 20:32:33,038 INFO     MoM sent signal -HUP
2021-02-04 20:32:33,038 INFOCLI2 pbsdev-centos7-mky18-mom1: ssh pbsdev-centos7-mky18-mom1.pbsdev-centos7-mky18.local sudo -H /usr/bin/cat /var/spool/pbs/mom_priv/mom.lock
2021-02-04 20:32:33,063 INFOCLI2 pbsdev-centos7-mky18-mom1: ssh pbsdev-centos7-mky18-mom1.pbsdev-centos7-mky18.local sudo -H kill -HUP 16794
2021-02-04 20:32:33,108 INFOCLI2 pbsdev-centos7-mky18-mom1: ssh pbsdev-centos7-mky18-mom1.pbsdev-centos7-mky18.local sudo -H /usr/bin/cat /var/spool/pbs/mom_priv/mom.lock
2021-02-04 20:32:33,133 INFO     status on pbsdev-centos7-mky18-server: node pbsdev-centos7-mky18-mom1
2021-02-04 20:32:33,134 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/pbsnodes -s pbsdev-centos7-mky18-server.pbsdev-centos7-mky18.local -v pbsdev-centos7-mky18-mom1
2021-02-04 20:32:33,143 ERROR    <DshUtils.run_cmd>err: ['/opt/pbs/bin/pbsnodes: Server has no node list']
2021-02-04 20:32:33,143 INFO     manager on pbsdev-centos7-mky18-server: create node pbsdev-centos7-mky18-mom1
2021-02-04 20:32:33,143 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/qmgr -c create node pbsdev-centos7-mky18-mom1
2021-02-04 20:32:33,158 INFO     status on pbsdev-centos7-mky18-server: node pbsdev-centos7-mky18-mom1
2021-02-04 20:32:33,158 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/pbsnodes -s pbsdev-centos7-mky18-server.pbsdev-centos7-mky18.local -v pbsdev-centos7-mky18-mom1
2021-02-04 20:32:33,168 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/pbsnodes -s pbsdev-centos7-mky18-server.pbsdev-centos7-mky18.local -v pbsdev-centos7-mky18-mom1
2021-02-04 20:32:33,178 INFO     expect on server pbsdev-centos7-mky18-server: state = free node pbsdev-centos7-mky18-mom1  got: state = state-unknown,down
2021-02-04 20:32:34,182 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/pbsnodes -s pbsdev-centos7-mky18-server.pbsdev-centos7-mky18.local -v pbsdev-centos7-mky18-mom1
2021-02-04 20:32:34,195 INFO     expect on server pbsdev-centos7-mky18-server: state = free node pbsdev-centos7-mky18-mom1 attempt: 2  got: state = state-unknown,down
2021-02-04 20:32:35,197 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/pbsnodes -s pbsdev-centos7-mky18-server.pbsdev-centos7-mky18.local -v pbsdev-centos7-mky18-mom1
2021-02-04 20:32:35,207 INFO     expect on server pbsdev-centos7-mky18-server: state = free node pbsdev-centos7-mky18-mom1 attempt: 3 ...  OK
2021-02-04 20:32:35,207 INFO     status on pbsdev-centos7-mky18-server: node pbsdev-centos7-mky18-mom1
2021-02-04 20:32:35,207 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/pbsnodes -s pbsdev-centos7-mky18-server.pbsdev-centos7-mky18.local -v pbsdev-centos7-mky18-mom1
2021-02-04 20:32:35,266 INFOCLI2 pbsdev-centos7-mky18-mom2: ssh pbsdev-centos7-mky18-mom2.pbsdev-centos7-mky18.local ls -1 /opt/pbs/python/bin/python
2021-02-04 20:32:35,302 INFOCLI2 pbsdev-centos7-mky18-mom2: ssh pbsdev-centos7-mky18-mom2.pbsdev-centos7-mky18.local /usr/bin/python3 -c "import sys; print(sys.platform)"
2021-02-04 20:32:35,357 INFOCLI2 pbsdev-centos7-mky18-mom2: ssh pbsdev-centos7-mky18-mom2.pbsdev-centos7-mky18.local sudo -H /usr/bin/cat /var/spool/pbs/mom_priv/mom.lock
2021-02-04 20:32:35,380 INFO     status on pbsdev-centos7-mky18-server: node pbsdev-centos7-mky18-mom2
2021-02-04 20:32:35,381 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/pbsnodes -s pbsdev-centos7-mky18-server.pbsdev-centos7-mky18.local -v pbsdev-centos7-mky18-mom2
2021-02-04 20:32:35,393 ERROR    <DshUtils.run_cmd>err: ['Node: pbsdev-centos7-mky18-mom2,  Error: Unknown node ']
2021-02-04 20:32:35,393 INFOCLI2 pbsdev-centos7-mky18-mom2: ssh pbsdev-centos7-mky18-mom2.pbsdev-centos7-mky18.local which rm
2021-02-04 20:32:35,411 INFOCLI2 pbsdev-centos7-mky18-mom2: ssh pbsdev-centos7-mky18-mom2.pbsdev-centos7-mky18.local sudo -H /usr/bin/rm -f /var/spool/pbs/mom_priv/epilogue
2021-02-04 20:32:35,438 INFOCLI2 pbsdev-centos7-mky18-mom2: ssh pbsdev-centos7-mky18-mom2.pbsdev-centos7-mky18.local sudo -H /usr/bin/rm -f /var/spool/pbs/mom_priv/prologue
2021-02-04 20:32:35,462 INFOCLI  pbsdev-centos7-mky18-mom2: ssh pbsdev-centos7-mky18-mom2.pbsdev-centos7-mky18.local sudo -H /opt/pbs/sbin/pbs_mom -s list
2021-02-04 20:32:35,556 INFOCLI2 pbsdev-centos7-mky18-mom2: ssh pbsdev-centos7-mky18-mom2.pbsdev-centos7-mky18.local /usr/bin/python3 -c "import tempfile;print(tempfile.mkstemp('PtlPbstmpcopy')[1])"
2021-02-04 20:32:35,606 INFOCLI2 pbsdev-centos7-mky18-mom2: ssh pbsdev-centos7-mky18-mom2.pbsdev-centos7-mky18.local which scp
2021-02-04 20:32:35,623 INFOCLI2 pbsdev-centos7-mky18-server: /usr/bin/scp /tmp/PtlPbsixjfo3qr pbsdev-centos7-mky18-mom2.pbsdev-centos7-mky18.local:/tmp/tmpy7v33melPtlPbstmpcopy
2021-02-04 20:32:35,649 INFOCLI2 pbsdev-centos7-mky18-mom2: ssh pbsdev-centos7-mky18-mom2.pbsdev-centos7-mky18.local which cp
2021-02-04 20:32:35,668 INFOCLI2 pbsdev-centos7-mky18-mom2: ssh pbsdev-centos7-mky18-mom2.pbsdev-centos7-mky18.local sudo -H /usr/bin/cp /tmp/tmpy7v33melPtlPbstmpcopy /var/spool/pbs/mom_priv/config
2021-02-04 20:32:35,694 INFOCLI2 pbsdev-centos7-mky18-mom2: ssh pbsdev-centos7-mky18-mom2.pbsdev-centos7-mky18.local /usr/bin/rm /tmp/tmpy7v33melPtlPbstmpcopy
2021-02-04 20:32:35,713 INFO     MoM sent signal -HUP
2021-02-04 20:32:35,713 INFOCLI2 pbsdev-centos7-mky18-mom2: ssh pbsdev-centos7-mky18-mom2.pbsdev-centos7-mky18.local sudo -H /usr/bin/cat /var/spool/pbs/mom_priv/mom.lock
2021-02-04 20:32:35,739 INFOCLI2 pbsdev-centos7-mky18-mom2: ssh pbsdev-centos7-mky18-mom2.pbsdev-centos7-mky18.local sudo -H kill -HUP 16730
2021-02-04 20:32:35,786 INFOCLI2 pbsdev-centos7-mky18-mom2: ssh pbsdev-centos7-mky18-mom2.pbsdev-centos7-mky18.local sudo -H /usr/bin/cat /var/spool/pbs/mom_priv/mom.lock
2021-02-04 20:32:35,813 INFO     status on pbsdev-centos7-mky18-server: node pbsdev-centos7-mky18-mom2
2021-02-04 20:32:35,813 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/pbsnodes -s pbsdev-centos7-mky18-server.pbsdev-centos7-mky18.local -v pbsdev-centos7-mky18-mom2
2021-02-04 20:32:35,823 ERROR    <DshUtils.run_cmd>err: ['Node: pbsdev-centos7-mky18-mom2,  Error: Unknown node ']
2021-02-04 20:32:35,823 INFO     manager on pbsdev-centos7-mky18-server: create node pbsdev-centos7-mky18-mom2
2021-02-04 20:32:35,824 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/qmgr -c create node pbsdev-centos7-mky18-mom2
2021-02-04 20:32:35,840 INFO     status on pbsdev-centos7-mky18-server: node pbsdev-centos7-mky18-mom2
2021-02-04 20:32:35,840 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/pbsnodes -s pbsdev-centos7-mky18-server.pbsdev-centos7-mky18.local -v pbsdev-centos7-mky18-mom2
2021-02-04 20:32:35,850 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/pbsnodes -s pbsdev-centos7-mky18-server.pbsdev-centos7-mky18.local -v pbsdev-centos7-mky18-mom2
2021-02-04 20:32:35,860 INFO     expect on server pbsdev-centos7-mky18-server: state = free node pbsdev-centos7-mky18-mom2  got: state = state-unknown,down
2021-02-04 20:32:36,865 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/pbsnodes -s pbsdev-centos7-mky18-server.pbsdev-centos7-mky18.local -v pbsdev-centos7-mky18-mom2
2021-02-04 20:32:36,878 INFO     expect on server pbsdev-centos7-mky18-server: state = free node pbsdev-centos7-mky18-mom2 attempt: 2  got: state = state-unknown,down
2021-02-04 20:32:37,880 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/pbsnodes -s pbsdev-centos7-mky18-server.pbsdev-centos7-mky18.local -v pbsdev-centos7-mky18-mom2
2021-02-04 20:32:37,889 INFO     expect on server pbsdev-centos7-mky18-server: state = free node pbsdev-centos7-mky18-mom2 attempt: 3 ...  OK
2021-02-04 20:32:37,890 INFO     status on pbsdev-centos7-mky18-server: node pbsdev-centos7-mky18-mom2
2021-02-04 20:32:37,890 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/pbsnodes -s pbsdev-centos7-mky18-server.pbsdev-centos7-mky18.local -v pbsdev-centos7-mky18-mom2
2021-02-04 20:32:37,899 INFO     manager on pbsdev-centos7-mky18-server: set sched default {'opt_backfill_fuzzy': 'off'}
2021-02-04 20:32:37,899 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/qmgr -c set sched default opt_backfill_fuzzy=off
2021-02-04 20:32:37,914 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H /usr/bin/cat /var/spool/pbs/server_priv/comm.lock
2021-02-04 20:32:37,924 INFO     ==============================================
2021-02-04 20:32:37,924 INFO     Completed TestPbsModifyvnodeStateChanges setUp
2021-02-04 20:32:37,924 INFO     ==============================================
2021-02-04 20:32:37,924 INFO     manager on pbsdev-centos7-mky18-server: set server {'log_events': 4095}
2021-02-04 20:32:37,925 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/qmgr -c set server log_events=4095
2021-02-04 20:32:37,935 INFO     status on pbsdev-centos7-mky18-server: hook
2021-02-04 20:32:37,936 INFO     manager on pbsdev-centos7-mky18-server: list hook
2021-02-04 20:32:37,936 INFOCLI  pbsdev-centos7-mky18-server: sudo -H /opt/pbs/bin/qmgr -c list hook
2021-02-04 20:32:37,953 INFO     manager on pbsdev-centos7-mky18-server: create hook s1234
2021-02-04 20:32:37,954 INFOCLI  pbsdev-centos7-mky18-server: sudo -H /opt/pbs/bin/qmgr -c create hook s1234
2021-02-04 20:32:37,973 INFO     status on pbsdev-centos7-mky18-server: hook s1234
2021-02-04 20:32:37,973 INFO     manager on pbsdev-centos7-mky18-server: list hook s1234
2021-02-04 20:32:37,973 INFOCLI  pbsdev-centos7-mky18-server: sudo -H /opt/pbs/bin/qmgr -c list hook s1234
2021-02-04 20:32:37,990 INFO     status on pbsdev-centos7-mky18-server: hook s1234
2021-02-04 20:32:37,990 INFO     manager on pbsdev-centos7-mky18-server: list hook s1234
2021-02-04 20:32:37,990 INFOCLI  pbsdev-centos7-mky18-server: sudo -H /opt/pbs/bin/qmgr -c list hook s1234
2021-02-04 20:32:38,008 INFO     manager on pbsdev-centos7-mky18-server: set hook s1234 {'event': 'modifyvnode', 'enabled': 'True', 'debug': 'True'}
2021-02-04 20:32:38,008 INFOCLI  pbsdev-centos7-mky18-server: sudo -H /opt/pbs/bin/qmgr -c set hook s1234 event=modifyvnode,enabled=True,debug=True
2021-02-04 20:32:38,028 INFO     status on pbsdev-centos7-mky18-server: server sync_mom_hookfiles_timeout
2021-02-04 20:32:38,028 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/qstat -Bf pbsdev-centos7-mky18-server.pbsdev-centos7-mky18.local
2021-02-04 20:32:38,037 INFO     Setting sync_mom_hookfiles_timeout to 15s
2021-02-04 20:32:38,038 INFO     manager on pbsdev-centos7-mky18-server: set server {'sync_mom_hookfiles_timeout': 15}
2021-02-04 20:32:38,038 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/qmgr -c set server sync_mom_hookfiles_timeout=15
2021-02-04 20:32:38,048 INFO     manager on pbsdev-centos7-mky18-server: import hook s1234 {'content-type': 'application/x-python', 'content-encoding': 'default', 'input-file': '/tmp/PtlPbsuwwpnuxj'}
2021-02-04 20:32:38,048 INFOCLI  pbsdev-centos7-mky18-server: sudo -H /opt/pbs/bin/qmgr -c import hook s1234 application/x-python default /tmp/PtlPbsuwwpnuxj
2021-02-04 20:32:38,067 INFO     server pbsdev-centos7-mky18-server: imported hook body
---

import pbs
import sys
try:
    e = pbs.event()
    v = e.vnode
    v_o = e.vnode_o
    lsct = v.last_state_change_time
    lsct_o = v_o.last_state_change_time
    state_str_buf_v = ",".join(v.extract_state_strs())
    state_str_buf_v_o = ",".join(v_o.extract_state_strs())
    state_int_buf_v = ','.join([str(_) for _ in v.extract_state_ints()])
    state_int_buf_v_o = ','.join(
        [str(_) for _ in v_o.extract_state_ints()])
    # print show_vnode_state record (bi consumable)
    svs1_data = "v.state_hex=%s v_o.state_hex=%s v.state_strs=%s "                     "v_o.state_strs=%s" %                     (hex(v.state), hex(v_o.state), state_str_buf_v,
                 state_str_buf_v_o)
    svs2_data = "v.state_ints=%s v_o.state_ints=%s v.lsct=%s "                     "v_o.lsct=%s" %                     (state_int_buf_v, state_int_buf_v_o, str(lsct),
                 str(lsct_o))
    svs_data = "%s %s" % (svs1_data, svs2_data)
    pbs.logmsg(pbs.LOG_DEBUG,
               "show_vnode_state;name=%s %s" % (v.name, svs_data))
    # print additional hook parameter values
    pbs.logmsg(pbs.LOG_DEBUG, "name: v=%s, v_o=%s" % (v.name, v_o.name))
    pbs.logmsg(pbs.LOG_DEBUG,
               "state: v=%s, v_o=%s" % (hex(v.state), hex(v_o.state)))
    pbs.logmsg(pbs.LOG_DEBUG, "last_state_change_time: v=%s, v_o=%s" % (
               str(lsct), str(lsct_o)))
    pbs.logmsg(pbs.LOG_DEBUG,
               "comment: v=%s, v_o=%s" % (v.comment, v_o.comment))
    pbs.logmsg(pbs.LOG_DEBUG,
               "aoe: v=%s, v_o=%s" % (v.current_aoe, v_o.current_aoe))
    pbs.logmsg(pbs.LOG_DEBUG, "in_mvn_host: v=%s, v_o=%s" % (
               v.in_multivnode_host, v_o.in_multivnode_host))
    pbs.logmsg(pbs.LOG_DEBUG, "jobs: v=%s, v_o=%s" % (v.jobs, v_o.jobs))
    pbs.logmsg(pbs.LOG_DEBUG, "Mom: v=%s, v_o=%s" % (v.Mom, v_o.Mom))
    pbs.logmsg(pbs.LOG_DEBUG,
               "ntype: v=%s, v_o=%s" % (hex(v.ntype), hex(v_o.ntype)))
    pbs.logmsg(pbs.LOG_DEBUG, "pcpus: v=%s, v_o=%s" % (v.pcpus, v_o.pcpus))
    pbs.logmsg(pbs.LOG_DEBUG,
               "pnames: v=%s, v_o=%s" % (v.pnames, v_o.pnames))
    pbs.logmsg(pbs.LOG_DEBUG, "Port: v=%s, v_o=%s" % (v.Port, v_o.Port))
    pbs.logmsg(pbs.LOG_DEBUG,
               "Priority: v=%s, v_o=%s" % (v.Priority, v_o.Priority))
    pbs.logmsg(pbs.LOG_DEBUG, "provision_enable: v=%s, v_o=%s" % (
               v.provision_enable, v_o.provision_enable))
    pbs.logmsg(pbs.LOG_DEBUG, "queue: v=%s, v_o=%s" % (v.queue, v_o.queue))
    pbs.logmsg(pbs.LOG_DEBUG, "res_assigned: v=%s, v_o=%s" % (
               v.resources_assigned, v_o.resources_assigned))
    pbs.logmsg(pbs.LOG_DEBUG, "res_avail: v=%s, v_o=%s" % (
               v.resources_available, v_o.resources_available))
    pbs.logmsg(pbs.LOG_DEBUG, "resv: v=%s, v_o=%s" % (v.resv, v_o.resv))
    pbs.logmsg(pbs.LOG_DEBUG, "resv_enable: v=%s, v_o=%s" % (
               v.resv_enable, v_o.resv_enable))
    pbs.logmsg(pbs.LOG_DEBUG,
               "sharing: v=%s, v_o=%s" % (v.sharing, v_o.sharing))
    # sanity test some values
    if (lsct < lsct_o) or (lsct_o <= 0):
        e.reject("last_state_change_time: bad timestamp value")
    else:
        pbs.logmsg(pbs.LOG_DEBUG, "last_state_change_time: good times")
    if (v.name != v_o.name) or (not v.name):
        e.reject(
            "name: vnode and vnode_o name values are null or mismatched")
    else:
        pbs.logmsg(pbs.LOG_DEBUG, "name: good names")
    if (isinstance(v.state, int)) and (isinstance(v_o.state, int)):
        pbs.logmsg(pbs.LOG_DEBUG, "state: good states")
    else:
        e.reject("state: bad state value")
    if len(v.extract_state_strs()) == len(v.extract_state_ints()):
        pbs.logmsg(pbs.LOG_DEBUG, "state sets: good v sets")
    else:
        e.reject("state sets: bad v sets")
    if len(v_o.extract_state_strs()) == len(v_o.extract_state_ints()):
        pbs.logmsg(pbs.LOG_DEBUG, "state sets: good v_o sets")
    else:
        e.reject("state sets: bad v_o sets")
    e.accept()
except SystemExit:
    pass
except:
    pbs.event().reject("%s hook failed with %s" % (
                       pbs.event().hook_name, sys.exc_info()[:2]))
---
2021-02-04 20:32:38,069 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H ls -l /opt/pbs/libexec/pbs_init.d
2021-02-04 20:32:38,080 INFO     running init script to stop pbs server on pbsdev-centos7-mky18-server.pbsdev-centos7-mky18.local using /etc/pbs.conf init_cmd=['sudo', '-H', 'PBS_START_SERVER=1', 'PBS_START_MOM=0', 'PBS_START_SCHED=0', 'PBS_START_COMM=0', '/opt/pbs/libexec/pbs_init.d', 'stop']
2021-02-04 20:32:38,081 INFOCLI2 pbsdev-centos7-mky18-server: /tmp/PtlPbsw5ete8ps
Contents of /tmp/PtlPbsw5ete8ps:
----------------------------------------
#!/bin/bash
sudo -H PBS_START_SERVER=1 PBS_START_MOM=0 PBS_START_SCHED=0 PBS_START_COMM=0 /opt/pbs/libexec/pbs_init.d stop
----------------------------------------
2021-02-04 20:32:43,686 INFOCLI2 pbsdev-centos7-mky18-server: /usr/bin/rm /tmp/PtlPbsw5ete8ps
2021-02-04 20:32:43,691 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H ls -l /opt/pbs/libexec/pbs_init.d
2021-02-04 20:32:43,703 INFO     running init script to start pbs server on pbsdev-centos7-mky18-server.pbsdev-centos7-mky18.local using /etc/pbs.conf init_cmd=['sudo', '-H', 'PBS_START_SERVER=1', 'PBS_START_MOM=0', 'PBS_START_SCHED=0', 'PBS_START_COMM=0', '/opt/pbs/libexec/pbs_init.d', 'start']
2021-02-04 20:32:43,704 INFOCLI2 pbsdev-centos7-mky18-server: /tmp/PtlPbspy7aiu_f
Contents of /tmp/PtlPbspy7aiu_f:
----------------------------------------
#!/bin/bash
sudo -H PBS_START_SERVER=1 PBS_START_MOM=0 PBS_START_SCHED=0 PBS_START_COMM=0 /opt/pbs/libexec/pbs_init.d start
----------------------------------------
2021-02-04 20:32:47,719 INFOCLI2 pbsdev-centos7-mky18-server: /usr/bin/rm /tmp/PtlPbspy7aiu_f
2021-02-04 20:32:47,725 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H /usr/bin/cat /var/spool/pbs/server_priv/server.lock
2021-02-04 20:32:47,736 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/qstat -Bf pbsdev-centos7-mky18-server.pbsdev-centos7-mky18.local
2021-02-04 20:32:47,751 INFO     server pbsdev-centos7-mky18-server log match: searching for "set_vnode_state;vnode.state=" - with existence - No match
2021-02-04 20:32:49,076 INFO     server pbsdev-centos7-mky18-server log match: searching for "set_vnode_state;vnode.state=" - with existence... OK
2021-02-04 20:32:49,083 INFO     server pbsdev-centos7-mky18-server log match: searching for "show_vnode_state;name=" - with existence... OK
2021-02-04 20:32:49,086 INFO     server pbsdev-centos7-mky18-server log match: searching for "name: v=" - with existence... OK
2021-02-04 20:32:49,088 INFO     server pbsdev-centos7-mky18-server log match: searching for "state: v=" - with existence... OK
2021-02-04 20:32:49,091 INFO     server pbsdev-centos7-mky18-server log match: searching for "last_state_change_time: v=" - with existence... OK
2021-02-04 20:32:49,093 INFO     server pbsdev-centos7-mky18-server log match: searching for "good times" - with existence... OK
2021-02-04 20:32:49,096 INFO     server pbsdev-centos7-mky18-server log match: searching for "good names" - with existence... OK
2021-02-04 20:32:49,098 INFO     server pbsdev-centos7-mky18-server log match: searching for "good states" - with existence... OK
2021-02-04 20:32:49,100 INFO     server pbsdev-centos7-mky18-server log match: searching for "good v sets" - with existence... OK
2021-02-04 20:32:49,103 INFO     server pbsdev-centos7-mky18-server log match: searching for "good v_o sets" - with existence... OK
2021-02-04 20:32:49,106 INFO     server pbsdev-centos7-mky18-server log match: searching for "Node;pbsdev-centos7-mky18-mom1.pbsdev-centos7-mky18.local;node up" - with existence - No match
2021-02-04 20:32:50,372 INFO     server pbsdev-centos7-mky18-server log match: searching for "Node;pbsdev-centos7-mky18-mom1.pbsdev-centos7-mky18.local;node up" - with existence... OK
2021-02-04 20:32:50,380 INFO     server pbsdev-centos7-mky18-server log match: searching for "v.state_hex=0x0" - with existence... OK
2021-02-04 20:32:50,383 INFO     server pbsdev-centos7-mky18-server log match: searching for "v.state_strs=ND_STATE_FREE" - with existence... OK
2021-02-04 20:32:50,386 INFO     server pbsdev-centos7-mky18-server log match: searching for "v.state_ints=0" - with existence... OK
2021-02-04 20:32:50,386 INFO     checkpreviousStateChain search_string=;show_vnode_state;name=pbsdev-centos7-mky18-mom1 start=1612470758.0675268 end=1612470770.386553
2021-02-04 20:32:50,421 INFO     server pbsdev-centos7-mky18-server log match: searching for ";show_vnode_state;name=pbsdev-centos7-mky18-mom1" - on all matches  - with existence... OK
2021-02-04 20:32:50,425 INFO     server pbsdev-centos7-mky18-server log match: searching for "set_vnode_state;vnode.state=" - with existence... OK
2021-02-04 20:32:50,427 INFO     server pbsdev-centos7-mky18-server log match: searching for "show_vnode_state;name=" - with existence... OK
2021-02-04 20:32:50,430 INFO     server pbsdev-centos7-mky18-server log match: searching for "name: v=" - with existence... OK
2021-02-04 20:32:50,433 INFO     server pbsdev-centos7-mky18-server log match: searching for "state: v=" - with existence... OK
2021-02-04 20:32:50,437 INFO     server pbsdev-centos7-mky18-server log match: searching for "last_state_change_time: v=" - with existence... OK
2021-02-04 20:32:50,439 INFO     server pbsdev-centos7-mky18-server log match: searching for "good times" - with existence... OK
2021-02-04 20:32:50,443 INFO     server pbsdev-centos7-mky18-server log match: searching for "good names" - with existence... OK
2021-02-04 20:32:50,446 INFO     server pbsdev-centos7-mky18-server log match: searching for "good states" - with existence... OK
2021-02-04 20:32:50,449 INFO     server pbsdev-centos7-mky18-server log match: searching for "good v sets" - with existence... OK
2021-02-04 20:32:50,451 INFO     server pbsdev-centos7-mky18-server log match: searching for "good v_o sets" - with existence... OK
2021-02-04 20:32:50,454 INFO     server pbsdev-centos7-mky18-server log match: searching for "Node;pbsdev-centos7-mky18-mom2.pbsdev-centos7-mky18.local;node up" - with existence... OK
2021-02-04 20:32:50,458 INFO     server pbsdev-centos7-mky18-server log match: searching for "v.state_hex=0x0" - with existence... OK
2021-02-04 20:32:50,460 INFO     server pbsdev-centos7-mky18-server log match: searching for "v.state_strs=ND_STATE_FREE" - with existence... OK
2021-02-04 20:32:50,463 INFO     server pbsdev-centos7-mky18-server log match: searching for "v.state_ints=0" - with existence... OK
2021-02-04 20:32:50,463 INFO     checkpreviousStateChain search_string=;show_vnode_state;name=pbsdev-centos7-mky18-mom2 start=1612470758.0675268 end=1612470770.4637852
2021-02-04 20:32:50,502 INFO     server pbsdev-centos7-mky18-server log match: searching for ";show_vnode_state;name=pbsdev-centos7-mky18-mom2" - on all matches  - with existence... OK
2021-02-04 20:32:50,503 INFO     ================================================
2021-02-04 20:32:50,503 INFO      Entered TestPbsModifyvnodeStateChanges tearDown
2021-02-04 20:32:50,503 INFO     ================================================
2021-02-04 20:32:50,504 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/qstat -Bf pbsdev-centos7-mky18-server.pbsdev-centos7-mky18.local
2021-02-04 20:32:50,514 INFO     status on pbsdev-centos7-mky18-server: job
2021-02-04 20:32:50,514 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/qstat -f @pbsdev-centos7-mky18-server.pbsdev-centos7-mky18.local
2021-02-04 20:32:50,728 INFO     status on pbsdev-centos7-mky18-server: sched
2021-02-04 20:32:50,729 INFO     manager on pbsdev-centos7-mky18-server: list sched
2021-02-04 20:32:50,729 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/qmgr -c list sched
2021-02-04 20:32:50,741 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H /usr/bin/chown -R root /var/spool/pbs/sched_priv
2021-02-04 20:32:50,752 INFO     scheduler pbsdev-centos7-mky18-server:  setting dedicated time file to /var/spool/pbs/sched_priv/dedicated_time
2021-02-04 20:32:50,763 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H /opt/pbs/sbin/pbsfs
2021-02-04 20:32:50,779 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H /usr/bin/cat /var/spool/pbs/sched_priv/resource_group
2021-02-04 20:32:50,791 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H /usr/bin/cat /var/spool/pbs/sched_priv/holidays
2021-02-04 20:32:50,801 INFO     manager on pbsdev-centos7-mky18-server as root: set sched default {'scheduling': 'False'}
2021-02-04 20:32:50,802 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/qmgr -c set sched default scheduling=False
2021-02-04 20:32:50,814 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/qmgr -c list sched default
2021-02-04 20:32:50,824 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H /usr/bin/chown -R root /var/spool/pbs/sched_priv
2021-02-04 20:32:50,835 INFO     scheduler pbsdev-centos7-mky18-server:  setting dedicated time file to /var/spool/pbs/sched_priv/dedicated_time
2021-02-04 20:32:50,847 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H /opt/pbs/sbin/pbsfs
2021-02-04 20:32:50,864 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H /usr/bin/cat /var/spool/pbs/sched_priv/resource_group
2021-02-04 20:32:50,877 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H /usr/bin/cat /var/spool/pbs/sched_priv/holidays
2021-02-04 20:32:50,888 INFO     expect on server pbsdev-centos7-mky18-server: state != scheduling sched default ...  OK
2021-02-04 20:32:50,888 INFO     delete job on pbsdev-centos7-mky18-server as root:
2021-02-04 20:32:50,888 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/qstat -f @pbsdev-centos7-mky18-server.pbsdev-centos7-mky18.local
2021-02-04 20:32:51,105 INFO     expect on server pbsdev-centos7-mky18-server: job_state set 0 job ...  OK
2021-02-04 20:32:51,105 INFO     manager on pbsdev-centos7-mky18-server as root: set sched default {'scheduling': 'True'}
2021-02-04 20:32:51,105 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/qmgr -c set sched default scheduling=True
2021-02-04 20:32:51,117 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/qmgr -c list sched default
2021-02-04 20:32:51,127 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H /usr/bin/chown -R root /var/spool/pbs/sched_priv
2021-02-04 20:32:51,138 INFO     scheduler pbsdev-centos7-mky18-server:  setting dedicated time file to /var/spool/pbs/sched_priv/dedicated_time
2021-02-04 20:32:51,150 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H /opt/pbs/sbin/pbsfs
2021-02-04 20:32:51,166 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H /usr/bin/cat /var/spool/pbs/sched_priv/resource_group
2021-02-04 20:32:51,177 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H /usr/bin/cat /var/spool/pbs/sched_priv/holidays
2021-02-04 20:32:51,188 INFO     expect on server pbsdev-centos7-mky18-server: scheduling = True sched default ...  OK
2021-02-04 20:32:51,188 INFO     manager on pbsdev-centos7-mky18-server: list sched
2021-02-04 20:32:51,188 INFOCLI  pbsdev-centos7-mky18-server: /opt/pbs/bin/qmgr -c list sched
2021-02-04 20:32:51,199 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H /usr/bin/chown -R root /var/spool/pbs/sched_priv
2021-02-04 20:32:51,210 INFO     scheduler pbsdev-centos7-mky18-server:  setting dedicated time file to /var/spool/pbs/sched_priv/dedicated_time
2021-02-04 20:32:51,222 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H /opt/pbs/sbin/pbsfs
2021-02-04 20:32:51,238 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H /usr/bin/cat /var/spool/pbs/sched_priv/resource_group
2021-02-04 20:32:51,249 INFOCLI2 pbsdev-centos7-mky18-server: sudo -H /usr/bin/cat /var/spool/pbs/sched_priv/holidays
2021-02-04 20:32:51,259 INFO     =================================================
2021-02-04 20:32:51,260 INFO     Completed TestPbsModifyvnodeStateChanges tearDown
2021-02-04 20:32:51,260 INFO     =================================================
2021-02-04 20:32:51,261 INFOCLI2 pbsdev-centos7-mky18-mom1: ssh pbsdev-centos7-mky18-mom1.pbsdev-centos7-mky18.local /usr/bin/python3 -c "import platform;print(' '.join(platform.uname()))"
2021-02-04 20:32:51,315 INFOCLI2 pbsdev-centos7-mky18-mom1: ssh pbsdev-centos7-mky18-mom1.pbsdev-centos7-mky18.local /usr/bin/python3 -c "import platform; print(platform.platform())"
2021-02-04 20:32:51,371 INFOCLI2 pbsdev-centos7-mky18-mom2: ssh pbsdev-centos7-mky18-mom2.pbsdev-centos7-mky18.local /usr/bin/python3 -c "import platform;print(' '.join(platform.uname()))"
2021-02-04 20:32:51,425 INFOCLI2 pbsdev-centos7-mky18-mom2: ssh pbsdev-centos7-mky18-mom2.pbsdev-centos7-mky18.local /usr/bin/python3 -c "import platform; print(platform.platform())"
2021-02-04 20:32:51,482 INFO     ok

2021-02-04 20:32:51,483 INFO     ================================================================================
run: 1, succeeded: 1, failed: 0, errors: 0, skipped: 0, timedout: 0
Tests run in 0:00:35.614050
2021-02-04 20:32:51,483 INFO     Cleaning up temporary files
2021-02-04 20:32:51,483 INFO     Cleaning up /tmp dir
2021-02-04 20:32:51,484 INFO     Cleaning up /var/tmp dir

real	0m35.916s
user	0m5.884s
sys	0m3.090s
[02/04 20:32:51] pbsdev@pbsdev-centos7-mky18-server:~ 56%