perfSONAR User Q&A and Other Discussion

["Uhl, George D. (GSFC-423.0)[SGT INC]" <>]

Hi Ivan,

The tests are running but they are only getting posted to the old archive  (see pscheduler results json snippet below that posts a single test run to both archives).  Using tcpdump on both archives, I see test result traffic from the testpoints arriving on port 443 and the httpd ssl access logs are recording the incoming traffic.  I just can’t find out what’s happening to the data after it arrives at the new archive.

From the ssl access log:

Testpoint - - [04/Oct/2018:17:29:47 +0000] “PUT /esmond/perfsonar/archive/079d1fe82ae840bf81f25b9138aa567c/ HTTP/1.1” 201 2

Thanks,

George 

  "archivings": [

    {

      "archived": true,

      "completed": true,

      "diags": [

        {

          "return-code": 0,

          "time": "2018-10-04T17:18:34Z",

          "stderr": "",

          "stdout": {

            "succeeded": true

          }

        }

      ],

      "archiver": {

        "schema": 1,

        "version": "1.0",

        "maintainer": {

          "href": "http://www.perfsonar.net",

          "name": "perfSONAR Development Team",

          "email": ""

        },

        "description": "Send results to Esmond",

        "name": "esmond"

      },

      "archiver_data": {

        “url”: “https://old-archive/esmond/perfsonar/archive/",

        “measurement-agent”: “test-host",

        "_auth-token": null

      },

      "last_attempt": "2018-10-04T13:18:34.173441-04:00"

    },

    {

      "archived": true,

      "completed": true,

      "diags": [

        {

          "return-code": 0,

          "time": "2018-10-04T17:18:34Z",

          "stderr": "",

          "stdout": {

            "succeeded": true

          }

        }

      ],

      "archiver": {

        "schema": 1,

        "version": "1.0",

        "maintainer": {

          "href": "http://www.perfsonar.net",

          "name": "perfSONAR Development Team",

          "email": ""

        },

        "description": "Send results to Esmond",

        "name": "esmond"

      },

      "archiver_data": {

        “url”: “https://new-archive/esmond/perfsonar/archive/",

        “measurement-agent”: “test-host",

        "_auth-token": null

      },

      "last_attempt": "2018-10-04T13:18:34.134074-04:00"

    }

  ],

From: "Garnizov, Ivan" <>
Date: Thursday, October 4, 2018 at 12:56 PM
To: George Uhl <>, Andrew Lake <>
Cc: perfsonar-user <>
Subject: AW: [non-nasa source] [perfsonar-user] FW: http POST 500 527 errors on central archive

Hello George,

 

In your case I would check the logs of pscheduler and even review the output of the runs they pass. There you should find traces of reports, which indicate the success or failure to submit the results from measurements to the archive. Thus you will make sure your configuration is propagated to pScheduler and the results are pushed to the new measurement archive.

Also you should expect some delay on seeing the results on the new Esmond. Since pScheduler will not consider your configuration changes within the first 24h of the setup.

 

Best regards,

Ivan

 

Jubiläumsjahr 2018 - IT in Bewegung

Das RRZE - der IT-Dienstleister der FAU

www.50-jahre.rrze.fau.de

 

Von: [] Im Auftrag von Uhl, George D. (GSFC-423.0)[SGT INC]
Gesendet: Donnerstag, 4. Oktober 2018 17:04
An: Andrew Lake <>
Cc: perfsonar-user <>
Betreff: Re: [non-nasa source] [perfsonar-user] FW: http POST 500 527 errors on central archive

 

Hi Andy,

 

Although I’m not getting any 500 errors anymore, my dashboard on the new archive server is showing “Unable to find test data” on all my grids.   I’m posting data to both the old and new archives and the dashboard on the old archive is humming along just fine.

 

When I run the esmond manage python scripts on my new archive server now, I get the same API key that was generated on the old archive server.  However when I first set up esmond the new archive server the API key was different and it changed sometime during the migration process.  Could it be an authentication issue that occurred after I migrated the legacy data from my old server?  I can’t find anything in the logs that would indicate that my my data is not getting into esmond.  On the new archive when I do a drill down into esmond for a test results from a particular test, I get this:

 

# curl -k https://127.0.0.1/esmond/perfsonar/archive/3ece56b01cf64e47a08057334a2b109a/

{"url":"https://127.0.0.1/esmond/perfsonar/archive/3ece56b01cf64e47a08057334a2b109a/","metadata-key":"3ece56b01cf64e47a08057334a2b109a","subject-type":"point-to-point","event-types":[],"uri":"/esmond/perfsonar/archive/3ece56b01cf64e47a08057334a2b109a/"}

 

Thanks,

George

 

From: Andrew Lake <>
Date: Thursday, October 4, 2018 at 10:32 AM
To: George Uhl <>
Cc: perfsonar-user <>
Subject: Re: [non-nasa source] [perfsonar-user] FW: http POST 500 527 errors on central archive

 

Hi George,

 

Glad you were able to find the source of the issue. I captured the info you shared in a documentation issue. It sounds like we should make a note of that somewhere since it is not immediately obvious the cause but easy to run into. 

 

Thanks,
Andy

 

 

 

 

On Wed, Oct 3, 2018 at 4:35 PM Uhl, George D. (GSFC-423.0)[SGT INC] <> wrote:

Andy,

 

It turns out it was an selinux issue.  I’m running enforcing/active and somehow the esmond.log file was impacted after I attempted to migrate the data this morning.  I dug around and found an email from Jon Clausen dated Thurs Sep 14, 2017, 5:56 am and followed the procedure outlined (see below).  It worked – the HTTP 500 errors have stopped.  I’m going to change selinux to permissive and go from there.  How/why this stopped working is still unknown.

 

Thanks,

George

 

=============

Hi

 

Our measurement archive is installed from the CentOS 7 *.iso, with perfSonar

components installed from the internet2 repo.

 

I chose to leave SELinux active/enforcing, which is actually not causing

many problems, generally - to my pleasant surprise.

 

The system has yum-cron installed, so updates happen 'whenever'.

 

Early this morning there were a lot of package updates, and subsequently the

toolkit URL was unable to load test results, showing an 'internal server

error' message instead.

 

The cause turned out to be a change in SELinux 'type' on a couple of log

files, which resulted in permission denied errors in

/var/log/httpd/error_log

 

[Thu Sep 14 10:59:19.652856 2017] [:error] [pid 14147] [remote

109.105.99.90:132

] ValueError: Unable to configure handler 'esmond_handler': [Errno 13]

Permission denied: '/var/log/esmond/esmond.log'

 

The 'cure' would have been to change object type using chcon, or as I did:

move the log file out of the way and restart apache.

 

The object type change can be seen here:

[jac@psma01 ~]$ ls -Z /var/log/esmond/esmond.log*

-rw-r--r--. apache apache system_u:object_r:httpd_log_t:s0

/var/log/esmond/esmond.log

-rw-r--r--. apache apache system_u:object_r:var_log_t:s0

/var/log/esmond/esmond.log.2017-08-21

 

 

This mail is mostly a 'heads up' to other people running the measurement

archive under SELinux, but I guess the info may be relevant to the perfSonar

packagers too.

 

Should I submit the info somwhere?

 

br

/jon

-- 

 

 

From: <> on behalf of George Uhl <>
Date: Wednesday, October 3, 2018 at 4:12 PM
To: Andrew Lake <>
Cc: perfsonar-user <>
Subject: Re: [non-nasa source] [perfsonar-user] FW: http POST 500 527 errors on central archive

 

Andy,

 

The log files were not copied from the old server.  I did a chmod on esmond.log to 666 but that didn’t help either.

 

Thanks,

George

 

# ls -la /var/log/esmond

total 5056

drwxr-xr-x.  3 apache apache     177 Oct  3 14:23 .

drwxr-xr-x. 15 root   root      4096 Oct  3 19:11 ..

drwxr-xr-x.  2 apache apache       6 Mar 15  2018 crashlog

-rw-r--r--.  1 apache apache 5108885 Oct  3 14:52 django.log

-rw-r--r--.  1 apache apache    8230 Oct  3 14:23 django.log.1

-rw-r--r--.  1 apache apache    8480 Oct  3 14:23 django.log.2

-rw-r--r--.  1 apache apache    8480 Oct  3 14:23 django.log.3

-rw-r--r--.  1 apache apache   12720 Oct  3 14:23 django.log.4

-rw-r--r--.  1 apache apache    4240 Oct  3 14:23 django.log.5

-rw-rw-rw-.  1 apache apache       0 Mar 15  2018 esmond.log

-rw-r--r--.  1 apache apache       0 Mar 15  2018 install.log

 

From: Andrew Lake <>
Date: Wednesday, October 3, 2018 at 4:00 PM
To: George Uhl <>
Cc: perfsonar-user <>
Subject: Re: [non-nasa source] [perfsonar-user] FW: http POST 500 527 errors on central archive

 

Hi George,

 

The error you are seeing is about the log permissions. Make sure the log files under /var/log/esmond are owned by the "apache" user then restart httpd. Did you copy over logs from the old host as well?

 

Thanks,
Andy

 

 

 

On Wed, Oct 3, 2018 at 3:51 PM Uhl, George D. (GSFC-423.0)[SGT INC] <> wrote:

It appears that the existing user api key was overwritten during the migration process.  Running both

 

/usr/sbin/esmond_manage add_ps_metadata_post_user

/usr/sbin/esmond_manage add_timeseries_post_user

reveal that the Key was changed to the value in the old archive for the user.  Changing the auth-token

in the archives.d/*.json file on the testpoint servers didn’t help. I’m still getting HTTP  500 errors.

 

-George

 

From: <> on behalf of George Uhl <>
Date: Wednesday, October 3, 2018 at 1:52 PM
To: "" <>
Subject: [non-nasa source] [perfsonar-user] FW: http POST 500 527 errors on central archive

 

 

 

From: George Uhl <>
Date: Wednesday, October 3, 2018 at 1:38 PM
To: "" <>
Subject: http POST 500 527 errors on central archive

 

I attempted to migrate data from an older pS archive to one built on pS 4.1 by following these instructions.  Unfortunately once I had completed the migration none of my pS testpoint servers are able to post data into esmond. Now I’m getting Code 500 errors instead.

 

Thanks,

George

 

From ssl error log:

Wed Oct 03 17:30:37.021250 2018] [:error] [pid 2836] [remote x.x.x.x:y] mod_wsgi (pid=2836): Exception occurred processing WSGI script ‘/usr/lib/esmond/esmond/wsgi.py’.

[Wed Oct 03 17:30:37.021312 2018] [:error] [pid 2836] [remote x.x.x.x:y] Traceback (most recent call last):

[Wed Oct 03 17:30:37.021344 2018] [:error] [pid 2836] [remote x.x.x.x:y]   File "/usr/lib/esmond/esmond/wsgi.py", line 28, in application

[Wed Oct 03 17:30:37.021433 2018] [:error] [pid 2836] [remote x.x.x.x:y]     return get_wsgi_application()(environ, start_response)

[Wed Oct 03 17:30:37.021452 2018] [:error] [pid 2836] [remote x.x.x.x:y]   File "/usr/lib/esmond/lib/python2.7/site-packages/django/core/wsgi.py", line 13, in get_wsgi_application

[Wed Oct 03 17:30:37.021482 2018] [:error] [pid 2836] [remote x.x.x.x:y]     django.setup(set_prefix=False)

[Wed Oct 03 17:30:37.021496 2018] [:error] [pid 2836] [remote x.x.x.x:y]   File "/usr/lib/esmond/lib/python2.7/site-packages/django/__init__.py", line 22, in setup

[Wed Oct 03 17:30:37.021520 2018] [:error] [pid 2836] [remote x.x.x.x:y]     configure_logging(settings.LOGGING_CONFIG, settings.LOGGING)

[Wed Oct 03 17:30:37.021533 2018] [:error] [pid 2836] [remote x.x.x.x:y]   File "/usr/lib/esmond/lib/python2.7/site-packages/django/utils/log.py", line 75, in configure_logging

[Wed Oct 03 17:30:37.021558 2018] [:error] [pid 2836] [remote x.x.x.x:y]     logging_config_func(logging_settings)

[Wed Oct 03 17:30:37.021572 2018] [:error] [pid 2836] [remote x.x.x.x:y]   File "/usr/lib64/python2.7/logging/config.py", line 803, in dictConfig

[Wed Oct 03 17:30:37.021597 2018] [:error] [pid 2836] [remote x.x.x.x:y]     dictConfigClass(config).configure()

[Wed Oct 03 17:30:37.021610 2018] [:error] [pid 2836] [remote x.x.x.x:y]   File "/usr/lib64/python2.7/logging/config.py", line 585, in configure

[Wed Oct 03 17:30:37.021633 2018] [:error] [pid 2836] [remote x.x.x.x:y]     '%r: %s' % (name, e))

[Wed Oct 03 17:30:37.021662 2018] [:error] [pid 2836] [remote x.x.x.x:y] ValueError: Unable to configure handler 'esmond_handler': [Errno 13] Permission denied: '/var/log/esmond/esmond.log'

 

 

From ssl request log:

[03/Oct/2018:17:35:42 +0000] x.x.x.x TLSv1.2 ECDHE-RSA-AES128-GCM-SHA256 "POST /esmond/perfsonar/archive/ HTTP/1.1" 527

 

 

From ssl access log:

x.x.x.x - - [03/Oct/2018:17:35:28 +0000] “POST /esmond/perfsonar/archive/ HTTP/1.1” 500 527