BlockReplicas API returns not what was requested

[nataliaratnikova]

The API intended logic is

PHEDEX/perl_lib/PHEDEX/Web/API/BlockReplicas.pm

Lines 288 to 291 in 0702117

	if ((not $p{BLOCK}) && (not $p{DATASET}) && (not $p{NODE}) && (not $p{CREATE_SINCE}))
	{
	$p{CREATE_SINCE} = "-1d";
	}

that is if none of block, dataset, node, or create_since is set, the default create_since is set to 1 day ago. If any is set, create_since is set to whatever the parameter is or open. Respective code:

Sometimes however the query returns all data sets subscribed in the last 24 hours even when not intended and confuses the calling application.

Affected version: 2_4_0-pre1 and earlier releases.

[nataliaratnikova]

Findings:

• When called with a missing dataset name: https://cmsweb.cern.ch/phedex/datasvc/json/prod/blockreplicas?dataset= , the API falls back to default behavior. This is consistently reproducible.
• Dynamo plots using this API for monitoring of total number of subscription, have semi-regular spikes, started a few weeks ago, then disappeared:
  http://dynamo.mit.edu/dynamo/dealermon/main.php?serviceId=2

These were the times (rounded to the quarter-hour) where we queried phedex and got the crazy responses.
2018-10-17 00:30:00 EDT
2018-10-19 02:15:00 EDT
2018-10-20 18:45:00 EDT
2018-10-22 12:00:00 EDT

Since three days I am querying the blockreplicas with the GluGlu dataset, every 20 seconds, and I havent observed a glitch so far. All the JSONs have exactly the same content ...

• Unified:
  • transfer request https://cmsweb.cern.ch/phedex/prod/Request::View?request=1492730
    contains non intended data from the recent subscriptions, which indicates a fall-back to default behavior
  • introduced a work around protect for blocks not in the dataset CMSCompOps/WmAgentScripts#330
  • added monitoring for bad returns and recorded a case of wrong output with a non-empty dataset name, coinciding with a frontend error due to expired certificate on the client host

[nataliaratnikova]

Possible solutions:

• A calling client software can check that output strictly corresponds to the input dataset.
• Provide a safe version of the BlockReplicas API for critical applications and to avoid confusions. Make the dataset or block parameter strictly required and disable the 24 hours default behavior.
  The old API can stay for the backward compatibility with an thing else that may be using the fall-back feature.

[nataliaratnikova]

Second case of misbehavior caught by Unified on Sat Nov 10 04:06 .
Again, no errors on the data service side, however, frontend servers that were handling the request have error messages about the expired CN=dmwm/cmsweb.cern.ch certificate (note, this is different from the DN that was used to used with the data service query and belonged to Jean-Roch.)

[bbockelm]

Hi @nataliaratnikova -

What's the error message that was received?

Brian

[nataliaratnikova]

I forwarded it to you in email.

[bbockelm]

For reference, the sanitized version is:

[Sat Nov 10 04:06:14.221283 2018] [ssl:error] [pid 13098] [client $CLIENT_IP] Certificate Verification: Error (10): certificate has expired; subject: $SUBJECT, issuer: $ISSUER, notbefore: Dec  9 15:36:15 2016 GMT, notafter: Jan 13 15:36:15 2018 GMT

One surprising thing I've recently learned is that Apache worker processes never reload CRLs -- meaning busy servers will never reload the CRLs and, in extreme cases, eventually start spewing expiration errors (only fix is to have the parent forcibly reload the child every N requests). I'm not sure this is the case here - but if we're fairly certain the certificate itself isn't expiring, we should look at the average age of the process and compare it to the CRL ages.

[vlimant]

can one explain how that expired cert lead to the query made be changed and replied to with something different than what was requested initially ; sorry but I am missing this point.

The call was for https://cmsweb.cern.ch/phedex/datasvc/xml/prod/blockreplicas?dataset=/MonoHbb_ZpBaryonic_MZp-500_MChi2-1_MChi1-0p5_ctau-100000_13TeV-madgraph/RunIISummer16MiniAODv2-PUMoriond17_80X_mcRun2_asymptotic_2016_TrancheIV_v6-v1/MINIAODSIM and returned block locations for [u'/DoubleMuon/Run2018C-PromptReco-v1/AOD#7057f19b-f644-4fd4-a779-047e63f70ab4', u'/DoubleMuon/Run2018C-PromptReco-v1/AOD#c49a7c8b-525e-460e-b5e4-674ba073369c', u'/DoubleMuon/Run2018C-PromptReco-v1/AOD#fe9bb7ab-0072-4c2c-9c36-995683f9736c', u'/EGamma/Run2018A-HcalCalIsoTrkFilter-PromptReco-v3/ALCARECO#018492c6-d733-47e5-ac80-1d63d8b0af5b', u'/EGamma/Run2018A-HcalCalIsoTrkFilter-PromptReco-v3/ALCARECO#134e9b0a-a1d5-4587-82e2-22aedf4c997f', u'/EGamma/Run2018A-HcalCalIsoTrkFilter-PromptReco-v3/ALCARECO#30d60b8f-0344-4f65-b27b-f6a5368272c0', u'/EGamma/Run2018A-HcalCalIsoTrkFilter-PromptReco-v3/ALCARECO#3538588b-5380-4f6f-90e1-523a5d83aec8', u'/EGamma/Run2018A-HcalCalIsoTrkFilter-PromptReco-v3/ALCARECO#56bd71ef-4378-4b8e-a826-a867b6f1b51d', u'/EGamma/Run2018A-HcalCalIsoTrkFilter-PromptReco-v3/ALCARECO#5f5dc434-6a7a-4a28-9957-2d0febe19430', u'/EGamma/Run2018A-HcalCalIsoTrkFilter-PromptReco-v3/ALCARECO#7e78af93-4724-44ab-a976-6a187b3142c4', u'/EGamma/Run2018A-HcalCalIsoTrkFilter-PromptReco-v3/ALCARECO#844e11f0-9ef6-4ab3-b1d7-ca5fcd7e52b1', u'/EGamma/Run2018A-HcalCalIsoTrkFilter-PromptReco-v3/ALCARECO#93598e28-2ece-4db4-afc1-32e8ed002592', u'/EGamma/Run2018A-HcalCalIsoTrkFilter-PromptReco-v3/ALCARECO#b97e9a54-06b7-4b20-b24f-b5f319d79056', u'/EGamma/Run2018A-HcalCalIsoTrkFilter-PromptReco-v3/ALCARECO#c1ee19f5-1c11-4bdc-bea6-691de32764a1', u'/EGamma/Run2018A-HcalCalIsoTrkFilter-PromptReco-v3/ALCARECO#de35cfea-d12c-4ca9-98fa-ebccbe78d0b9'] for example

[bbockelm]

@vlimant - my working theory would be Apache has a bug and is spewing crap.

@nataliaratnikova - to make sure that I understand your message correctly, is the CN=dmwm/cmsweb.cern.ch certificate the one that the frontend uses to authenticate with the backend?

[nataliaratnikova]

HI Brian, I do not know much about frontend/backend authentication, I hoped you would know what this DN is for. I will ask via e-group for cmsweb developers and operators, hopefully we get an answer next week.

[amaltaro]

That certificate is "internally" used by CMSWEB services for inter-communication, though the frontend though.
Like in ReqMgr2, some ReqMgr2 APIs are internally querying couchdb, those queries are not local, so they again go through the frontends and in order to get those requests authenticated, those services have a copy of the dmwm/cmsweb service certificate in their area.

[bbockelm]

@amaltaro - do we have monitoring for the age of the certificates? Is it safe to assume that these did not really expire?

Back to my earlier comment:

we should look at the average age of the process and compare it to the CRL ages.

The only way I know to test this theory is to have someone log in to the frontend and look at the age of the Apache worker processes. If they are regularly a few days old, we could be hitting this bug.

[amaltaro]

I think Lina is going to reply to this thread, but there is no monitoring. The service certificate gets copied during the deployment to its own service auth area. Meaning either it works all the time, without any room for glitches or very short windows of expiration, OR... I wouldn't discard the change to have a unwanted backend serving requests with an expired certificated (e.g., reqmgr2 on vocms0742, which does not serve any requests, but if it had to, it would have expired certs).

I let Lina comment any further, we should have the backend ip address on the frontend logs and be able to rule out that theory.

[bbockelm]

Gotcha. Since we're not seeing massive failures across the board, I'm going to guess that it's not really expired. I feel like my CRL theory may be going down the right track.

@h4d4 - can you do ps faux | grep httpd on one of the frontend nodes (that's where Natalia is seeing the failure, right)? For example, on one of my development hosts, the output is this:

root     30861  0.0  0.0 273388  9476 ?        Ss   Aug08  11:20 /usr/sbin/httpd -DFOREGROUND
apache   15726  0.0  0.0 287972 11108 ?        S    Nov18   0:00  \_ /usr/sbin/httpd -DFOREGROUND
apache   15727  0.0  0.0 287940 11144 ?        S    Nov18   0:00  \_ /usr/sbin/httpd -DFOREGROUND
apache   15728  0.0  0.0 287980 11108 ?        S    Nov18   0:01  \_ /usr/sbin/httpd -DFOREGROUND
apache   15729  0.0  0.0 287952 11120 ?        S    Nov18   0:00  \_ /usr/sbin/httpd -DFOREGROUND
apache   15730  0.0  0.0 287952 11124 ?        S    Nov18   0:00  \_ /usr/sbin/httpd -DFOREGROUND
apache   23671  0.0  0.0 287988 11136 ?        S    Nov18   0:00  \_ /usr/sbin/httpd -DFOREGROUND
apache   18290  0.0  0.0 287980 11128 ?        S    Nov18   0:00  \_ /usr/sbin/httpd -DFOREGROUND
apache   25207  0.0  0.0 287980 11084 ?        S    12:09   0:00  \_ /usr/sbin/httpd -DFOREGROUND
apache   26923  0.0  0.0 287916 10944 ?        S    12:18   0:00  \_ /usr/sbin/httpd -DFOREGROUND

So the majority of processes are from yesterday (Nov18); if we had a CRL that expired on 19 November, then that worker process would potentially have similar error messages to what Natalia is seeing. The leap-in-logic is really whether this additionally triggers some other bug related to returning the wrong data. That still feels like a pretty big leap to me!

Anyhow, we could potentially test this by having a custom frontend with one child and doing a steady stream of requests that require authentication for a week or so. Alternately, we could set:

MaxConnectionsPerChild 10000

in the frontend configuration and see if it lowers the average lifetime of the child process -- and see if this bug "magically" disappears.