perfSONAR User Q&A and Other Discussion

[Casey Russell <>]

Ivan,

     The log piece was in my 3rd email on the 13th, it would have been easy to miss.  yesterday afternoon I went ahead and upgraded my 4 lower powered hosts to the 4.0.2 beta and my dashboard is all green this morning, so it would appear everyone scheduled their tests last night, but I'll continue to monitor.  If / when I have another one act up, I'll follow your suggested steps and send you the results.

Thanks so much for your help.

Below you'll find a piece of the pscheduler log file from yesterday when one of these lower powered hosts was in the failed state and had failed to schedule most of its tests.  It appears that many of the tests that DID get scheduled failed at run time because pscheduler (or some component of pscheduler) was just to busy on this host to get the test initiated.

Oct 16 16:00:10 ps-washburn-bw runner INFO     7205482: Run failed 2: Process took too long to run.

Oct 16 16:00:13 ps-washburn-bw runner INFO     7239354: Run failed 2: Process took too long to run.

Oct 16 16:00:14 ps-washburn-bw pscheduler-api ERROR    Exception: InternalError: Unable to get merged result on {"test": {"spec": {"dest": "ps-wsu-bw.perfsonar.kanren.net", "schema": 1, "source": "ps-washburn-bw.perfsonar.kanren.net", "ip-version": 4}, "type": "trace"}, "results": [null]}: Process took too long to run.#012#012Traceback (most recent call last):#012  File "./pschedulerapiserver/runs.py", line 545, in tasks_uuid_runs_run#012  File "./pschedulerapiserver/dbcursor.py", line 112, in dbcursor_query#012InternalError: Unable to get merged result on {"test": {"spec": {"dest": "ps-wsu-bw.perfsonar.kanren.net", "schema": 1, "source": "ps-washburn-bw.perfsonar.kanren.net", "ip-version": 4}, "type": "trace"}, "results": [null]}: Process took too long to run.

Oct 16 16:00:14 ps-washburn-bw runner WARNING  7239157: Unable to update run https://ps-washburn-bw.perfsonar.kanren.net/pscheduler/tasks/28d2b84d-4d84-4d3e-a901-1a2d63425223/runs/ea10f21a-ba12-453b-b1c2-22988698c04d: 500 Unable to get merged result on {"test": {"spec": {"dest": "ps-wsu-bw.perfsonar.kanren.net", "schema": 1, "source": "ps-washburn-bw.perfsonar.kanren.net", "ip-version": 4}, "type": "trace"}, "results": [null]}: Process took too long to run.#012

Oct 16 16:00:41 ps-washburn-bw runner INFO     7190345: Run failed 2: Process took too long to run.

Oct 16 16:00:51 ps-washburn-bw scheduler INFO     24433: Posting non-starting run at 2017-10-17T08:38:23-05:00 for task eac7ccd1-386f-4fff-9e25-70ca2a124824: Failed to post/put runs to all participants: Failed to validate limit: Process took too long to run.

Oct 16 16:01:23 ps-washburn-bw runner INFO     7239232: Run failed 2: Process took too long to run.

Oct 16 16:01:24 ps-washburn-bw runner INFO     7204637: Run failed 2: Process took too long to run.

Oct 16 16:01:28 ps-washburn-bw pscheduler-api ERROR    Exception: RuntimeError: Failed to validate limit: Process took too long to run.#012Traceback (most recent call last):#012  File "./pschedulerapiserver/runs.py", line 171, in tasks_uuid_runs#012  File "./pschedulerapiserver/runs.py", line 85, in __evaluate_limits#012  File "/usr/lib/python2.6/site-packages/pscheduler/limitprocessor/limitprocessor.py", line 135, in process#012    = self.applications.check(task, classifications, check_schedule)#012  File "/usr/lib/python2.6/site-packages/pscheduler/limitprocessor/applicationset.py", line 225, in check#012    check_schedule)#012  File "/usr/lib/python2.6/site-packages/pscheduler/limitprocessor/applicationset.py", line 161, in __check_application#012    = self.__check_group(task, group, check_schedule)#012  File "/usr/lib/python2.6/site-packages/pscheduler/limitprocessor/applicationset.py", line 119, in __check_group#012    evaluated = self.limits.check(task, limit, check_schedule)#012  File "/usr/lib/python2.6/site-packages/pscheduler/limitprocessor/limitset.py", line 163, in check#012    evaluated = evaluator.evaluate(task)#012  File "/usr/lib/python2.6/site-packages/pscheduler/limitprocessor/limit/test.py", line 83, in evaluate#012    raise RuntimeError("Failed to validate limit: %s" % stderr)#012RuntimeError: Failed to validate limit: Process took too long to run.

Oct 16 16:01:28 ps-washburn-bw scheduler INFO     24433: Posting non-starting run at 2017-10-17T12:38:23-05:00 for task eac7ccd1-386f-4fff-9e25-70ca2a124824: Failed to post lead run: Failed to validate limit: Process took too long to run.

Oct 16 16:01:32 ps-washburn-bw runner INFO     7204994: Run failed 2: Process took too long to run.

Oct 16 16:01:35 ps-washburn-bw runner INFO     7224211: Run failed 2: Process took too long to run.

Oct 16 16:02:29 ps-washburn-bw runner INFO     7239380: Run failed 2: Process took too long to run.

Oct 16 16:04:12 ps-washburn-bw runner INFO     7240102: Run failed 2: Process took too long to run.

Oct 16 16:05:23 ps-washburn-bw runner INFO     7204624: Run failed 2: Process took too long to run.

Oct 16 16:06:49 ps-washburn-bw runner INFO     7206879: Run failed 2: Process took too long to run.

Sincerely,

Casey Russell

Network Engineer

785-856-9809

2029 Becker Drive, Suite 282
Lawrence, Kansas 66047

On Tue, Oct 17, 2017 at 3:49 AM, Garnizov, Ivan (RRZE) <> wrote:

Hi Casey,

 

I kind of missed the fact that you have log events about it. For sure it will be helpful to have them.

Please also run a diagnostic test on an impacted system with

service pscheduler-scheduler status

pscheduler ping <local_ip>

pscheduler ping <any_pSremotehost>

pscheduler task –debug rtt --count 5 --dest <any_remotehost>

 

 

 

Please also restart the pscheduler service only and run the above the above commands again.

 

 

Regards,

Ivan

 

From: Casey Russell [mailto:]
Sent: Montag, 16. Oktober 2017 21:15

To: Garnizov, Ivan (RRZE)
Cc:
Subject: Re: [perfsonar-user] meshconfig-agent-tasks not scheduling tasks regularly

 

Ivan,

 

     I hope I've understood your questions correctly.  When a host gets "broken" it does not seem to matter whether the scheduling request (pscheduer) is initiated from the local host or a remote host, it will fail because the "broken" host seems to time out (usually the logfile says some variation of "process took to long to run").  

 

    Sometimes it's because it failed to validate the limits file, sometimes there's no extra detail, it's just "host closed connection: process took too long to run" or something of the like. 

 

 

 

Sincerely,

Casey Russell

Network Engineer

785-856-9809

2029 Becker Drive, Suite 282
Lawrence, Kansas 66047

 

On Mon, Oct 16, 2017 at 10:21 AM, Garnizov, Ivan (RRZE) <> wrote:

Hello Casey,

 

I am about to create an issue report about it. Could you please also share, if an impacted system is able to negotiate tests upon external requests or gets totally isolated from the rest of the mesh failing on both external and internal measurement requests?

 

Regards,

Ivan Garnizov

 

From: Casey Russell [mailto:]
Sent: Montag, 16. Oktober 2017 16:24
To: Garnizov, Ivan (RRZE)
Cc:
Subject: Re: [perfsonar-user] meshconfig-agent-tasks not scheduling tasks regularly

 

Ivan,

 

     I'm running PS 4.0.1-1 across all the boxes I believe.  7 of the testing hosts run CentOS 6 and one runs CentOS 7.  It doesn't seem to matter which OS is in play, but my 4 lower powered hosts are somewhat more likely to see these failures than my bigger boxes.  They all share a identical limits.com file for pscheduler.

 

     When it happens, there's a small chance that if I leave that host alone, it may go ahead and schedule the failed tests the next day (and they'll run for 24 hours) but more likely than not, they'll fail again.  I've left them alone for as long as a couple of weeks and they may have scheduled tests for 3-4 days during that time.  The only way I've discovered to clear the problem is to reboot the node.  This will bring that node back into line for some period of time (maybe a day or two, maybe a couple of weeks).

 

     All of the intervals, lifetime minimums, and task renewal fudge factor style timers in the meshconfig-agent.conf file still have "#" in front of them to comment them out, so they should be running their default values.  The only thing I've added or modified in that file on any of the hosts should be the <mesh> statements.

 

Sincerely,

Casey Russell

Network Engineer

785-856-9809

2029 Becker Drive, Suite 282
Lawrence, Kansas 66047

 

On Mon, Oct 16, 2017 at 2:23 AM, Garnizov, Ivan (RRZE) <> wrote:

Hello Cassey,

 

Please share your version of the pS software.

Are you able to observe a pattern of the issue (timewise)?

Do the systems automatically recover the flow of measurements?

OR What steps are required for the schedule to be recovered?

Do you have any specifics in your meschconfig-agent.conf file or are you using the defaults?

More specifically have you adjusted the interval parameters in the conf file?

 

Regards,

Ivan

 

 

From: [mailto:] On Behalf Of Casey Russell
Sent: Freitag, 13. Oktober 2017 16:55
To:
Subject: [perfsonar-user] meshconfig-agent-tasks not scheduling tasks regularly

 

Group,

 

     I mentioned it some time back, when I thought it was a problem with my 4 lower powered hosts running out of CPU, but I've been chasing it ever since and it's hitting my larger hosts as well.  Ever since I upgraded to 4.0 several months ago, I've had an issue where regularly, my hosts stop scheduling tests from the mesh.  My dashboard today shows a mess of hosts that failed to schedule tests last night some of them are on their second, (or more) continuous day.

 

     I can't figure out if this is a problem with the mesh config file or on the hosts (although since it's spread everywhere, even a newly installed CentOS7 host) I'm leaning toward some problem in the mesh config file.

 

     I'm not sure what to give you that will help, so below you'll find some diagnostic commands from an affected host this morning that is only running bandwidth tests, none of the latency tests scheduled.

 

Any ideas or help is appreciated.

 

Sincerely,

Casey Russell

Network Engineer

785-856-9809

2029 Becker Drive, Suite 282
Lawrence, Kansas 66047

 

Since the latency tests were never scheduled, I don't have anything from the API to show you, the mesh config file is at:  

 

[root@ps-ksu-bw crussell]# pscheduler schedule

2017-10-13T09:47:54-05:00 - 2017-10-13T09:48:23-05:00  (Pending)

throughput --duration PT20S --source ps-fhsu-bw.perfsonar.kanren.net --ip-version 4 --dest ps-ksu-bw.perfsonar.kanren.net --parallel 1 (Run with tool 'iperf3')

https://localhost/pscheduler/tasks/75b82820-db17-4e89-ab92-4c736bc273f4/runs/05948429-c5bc-4f1e-8f78-2989c27bb954

 

 

2017-10-13T09:49:33-05:00 - 2017-10-13T09:49:52-05:00  (Pending)

throughput --bandwidth 920000000 --duration PT10S --source ps-esu-bw.perfsonar.kanren.net --ip-version 4 --dest ps-ksu-bw.perfsonar.kanren.net --parallel 1 --udp (Run with tool 'iperf3')

https://localhost/pscheduler/tasks/3b1c5c75-7c23-4cc2-a280-e5c288fcacd8/runs/2a53a85c-19c5-4810-8553-9d75ae2c0529

 

 

2017-10-13T09:52:08-05:00 - 2017-10-13T09:52:27-05:00  (Pending)

throughput --bandwidth 920000000 --duration PT10S --source ps-bryant-bw.perfsonar.kanren.net --ip-version 6 --dest ps-ksu-bw.perfsonar.kanren.net --parallel 1 --udp (Run with tool 'iperf3')

https://localhost/pscheduler/tasks/fae2a1a4-11d4-4cf6-ba76-70c1caa8189d/runs/bb1c3d43-7662-4774-8501-6aacdd79f5e4

 

 

2017-10-13T09:58:44-05:00 - 2017-10-13T09:59:03-05:00  (Pending)

throughput --bandwidth 920000000 --duration PT10S --source ps-bryant-bw.perfsonar.kanren.net --ip-version 4 --dest ps-ksu-bw.perfsonar.kanren.net --parallel 1 --udp (Run with tool 'iperf3')

https://localhost/pscheduler/tasks/c663e121-a11d-49b4-8f21-25d77ef2ff76/runs/26c16f16-7d61-4d82-ba57-36c55d154bb3

 

 

2017-10-13T10:07:36-05:00 - 2017-10-13T10:08:05-05:00  (Pending)

throughput --duration PT20S --source ps-ku-bw.perfsonar.kanren.net --ip-version 6 --dest ps-ksu-bw.perfsonar.kanren.net --parallel 1 (Run with tool 'iperf3')

https://localhost/pscheduler/tasks/b51ab890-6c4e-4e8f-acf8-422154073114/runs/59151f65-36b6-4298-bbe2-e7a67aef3713

 

 

2017-10-13T10:08:38-05:00 - 2017-10-13T10:08:57-05:00  (Pending)

throughput --bandwidth 920000000 --duration PT10S --source ps-ku-bw.perfsonar.kanren.net --ip-version 6 --dest ps-ksu-bw.perfsonar.kanren.net --parallel 1 --udp (Run with tool 'iperf3')

https://localhost/pscheduler/tasks/5fd54280-af27-4f9e-b1a9-b62462f3ce0c/runs/231f1eb1-5cda-4e39-9a3c-bfc18333dd06

 

 

2017-10-13T10:10:18-05:00 - 2017-10-13T10:10:47-05:00  (Pending)

throughput --duration PT20S --source ps-esu-bw.perfsonar.kanren.net --ip-version 6 --dest ps-ksu-bw.perfsonar.kanren.net --parallel 1 (Run with tool 'iperf3')

https://localhost/pscheduler/tasks/f38efff5-851f-4d4f-9388-155d25bfe288/runs/5a803842-539a-403a-ae31-7f2351d527cb

 

 

2017-10-13T10:10:49-05:00 - 2017-10-13T10:11:08-05:00  (Pending)

throughput --bandwidth 920000000 --duration PT10S --source ps-esu-bw.perfsonar.kanren.net --ip-version 6 --dest ps-ksu-bw.perfsonar.kanren.net --parallel 1 --udp (Run with tool 'iperf3')

https://localhost/pscheduler/tasks/efaf912b-a6ef-45f3-a54a-cf157fdd8734/runs/a4a72b62-362f-4b79-a0a6-fe19e841431e

 

 

2017-10-13T10:16:39-05:00 - 2017-10-13T10:17:08-05:00  (Pending)

throughput --duration PT20S --source ps-fhsu-bw.perfsonar.kanren.net --ip-version 6 --dest ps-ksu-bw.perfsonar.kanren.net --parallel 1 (Run with tool 'iperf3')

https://localhost/pscheduler/tasks/25f395da-0fdb-41e5-b2a1-ac2c260f7279/runs/a58da605-0bf2-4ada-97eb-f8753a029519

 

 

2017-10-13T10:36:46-05:00 - 2017-10-13T10:37:15-05:00  (Pending)

throughput --duration PT20S --source ps-esu-bw.perfsonar.kanren.net --ip-version 4 --dest ps-ksu-bw.perfsonar.kanren.net --parallel 1 (Run with tool 'iperf3')

https://localhost/pscheduler/tasks/48092447-bd16-4220-a849-34ca8a0889c8/runs/05e74fcc-a287-48cc-bd35-ff76c29f9ef5

 

 

 

[root@ps-ksu-bw crussell]# service pscheduler-runner status

runner (pid  13073) is running...

 

[root@ps-ksu-bw crussell]# service pscheduler-ticker status

ticker (pid  13071) is running...

 

[root@ps-ksu-bw crussell]# service pscheduler-archiver status

archiver (pid  13078) is running...

 

[root@ps-ksu-bw crussell]# service pscheduler-server status

pscheduler-server: unrecognized service

 

[root@ps-ksu-bw crussell]# service pscheduler-scheduler status

scheduler (pid  13090) is running...

 

[root@ps-ksu-bw crussell]# ps -ax | grep pscheduler

Warning: bad syntax, perhaps a bogus '-'? See /usr/share/doc/procps-3.2.8/FAQ

 3448 pts/0    S+     0:00 grep pscheduler

 8236 ?        Ss     0:17 postgres: pscheduler pscheduler 127.0.0.1(41520) idle   

13071 ?        Sl     0:42 /usr/bin/python /usr/libexec/pscheduler/daemons/ticker --daemon --pid-file /var/run/pscheduler-ticker.pid --dsn @/etc/pscheduler/database/database-dsn

13073 ?        Sl    21:20 /usr/bin/python /usr/libexec/pscheduler/daemons/runner --daemon --pid-file /var/run/pscheduler-runner.pid --dsn @/etc/pscheduler/database/database-dsn

13075 ?        Ss     1:20 postgres: pscheduler pscheduler 127.0.0.1(48114) idle   

13076 ?        Ss     9:40 postgres: pscheduler pscheduler 127.0.0.1(48116) idle   

13078 ?        S     67:00 /usr/bin/python /usr/libexec/pscheduler/daemons/archiver --daemon --pid-file /var/run/pscheduler-archiver.pid --dsn @/etc/pscheduler/database/database-dsn

13079 ?        Ss   360:11 postgres: pscheduler pscheduler 127.0.0.1(48118) idle   

13081 ?        Ss     8:31 postgres: pscheduler pscheduler 127.0.0.1(48122) idle   

13083 ?        Ss     0:00 postgres: pscheduler pscheduler 127.0.0.1(48126) idle   

13090 ?        Sl    65:19 /usr/bin/python /usr/libexec/pscheduler/daemons/scheduler --daemon --pid-file /var/run/pscheduler-scheduler.pid --dsn @/etc/pscheduler/database/database-dsn

13108 ?        Ss   115:36 postgres: pscheduler pscheduler 127.0.0.1(48132) idle   

13114 ?        Ss     0:00 postgres: pscheduler pscheduler 127.0.0.1(48136) idle   

28737 ?        Ss     0:01 postgres: pscheduler pscheduler 127.0.0.1(55217) idle   

[root@ps-ksu-bw crussell]# 

 

[root@ps-ksu-bw crussell]# service perfsonar-meshconfig-agent

usage: /etc/init.d/perfsonar-meshconfig-agent (start|stop|restart|help)

 

start      - start perfSONAR MeshConfig Agent

stop       - stop perfSONAR MeshConfig Agent

restart    - restart perfSONAR MeshConfig Agent if running by sending a SIGHUP or start if 

             not running

status     - Indicates if the service is running

help       - this screen

 

[root@ps-ksu-bw crussell]# service perfsonar-meshconfig-agent restart

/etc/init.d/perfsonar-meshconfig-agent stop: perfSONAR MeshConfig Agent stopped

waiting...

/usr/lib/perfsonar/bin/perfsonar_meshconfig_agent --config=/etc/perfsonar/meshconfig-agent.conf --pidfile=/var/run/perfsonar-meshconfig-agent.pid --logger=/etc/perfsonar/meshconfig-agent-logger.conf --user=perfsonar --group=perfsonar

/etc/init.d/perfsonar-meshconfig-agent start: perfSONAR MeshConfig Agent started

 

[root@ps-ksu-bw crussell]# tail -n 50 /var/log/perfsonar/meshconfig-agent.log 

2017/10/12 20:10:55 (8826) INFO> perfsonar_meshconfig_agent:438 main:: - Added 3 new tasks, and deleted 0 old tasks

2017/10/12 21:10:10 (8826) INFO> perfsonar_meshconfig_agent:438 main:: - Added 1 new tasks, and deleted 0 old tasks

2017/10/13 03:10:37 (8826) INFO> perfsonar_meshconfig_agent:438 main:: - Added 2 new tasks, and deleted 0 old tasks

2017/10/13 04:10:40 (8826) WARN> perfsonar_meshconfig_agent:430 main:: - Problem determining which pscheduler to submit test to for deletion, skipping test throughput/iperf3(ps-ksu-bw.perfsonar.kanren.net->ps-fhsu-bw.perfsonar.kanren.net): 500 Internal Server Error: <!DOCTYPE HTML PUBLIC "-//IETF//DTD HTML 2.0//EN">

<html><head>

<title>500 Internal Server Error</title>

</head><body>

<h1>Internal Server Error</h1>

<p>The server encountered an internal error or

misconfiguration and was unable to complete

your request.</p>

<p>Please contact the server administrator at 

 root@localhost to inform them of the time this error occurred,

 and the actions you performed just before this error.</p>

<p>More information about this error may be available

in the server error log.</p>

</body></html>

2017/10/13 07:11:39 (8826) INFO> perfsonar_meshconfig_agent:438 main:: - Added 5 new tasks, and deleted 0 old tasks

2017/10/13 09:20:23 (8826) INFO> perfsonar_meshconfig_agent:438 main:: - Added 97 new tasks, and deleted 0 old tasks