Mailing List Archives
Public Access
|
|
![[Computer Systems Lab]](https://www-auth.cs.wisc.edu/pics/csl_logo.gif)
|
[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]
Re: [HTCondor-users] CondorCE token subject mapping not working anymore
- Date: Tue, 18 Apr 2023 12:35:06 +0200
- From: Thomas Hartmann <thomas.hartmann@xxxxxxx>
- Subject: Re: [HTCondor-users] CondorCE token subject mapping not working anymore
Hi Jamie,
with the Security logging on debug level 2 I see a bit more. However, it
is still not really clear to me, what is the cause. The error is due to
the token not being verified and not mapped [1].
But from my opinion, the existing mapping [2] should match on the token
subject.
Cheers,
Thomas
[1]
04/18/23 12:24:18.282 (D_SECURITY) SciToken SSL read is successful.
04/18/23 12:24:22.680 (D_SECURITY) SCITOKENS:2:Failed to verify token
and generate ACLs: Timeout was reached
04/18/23 12:24:22.681 (D_SECURITY:2) AUTHENTICATION: map file already
loaded.
04/18/23 12:24:22.681 (D_ERROR) Failed to map SCITOKENS authenticated
identity '', failing authentication to give another authentication
method a go.
[2]
root@grid-htcondorce-dev02: [/etc/condor-ce/config.d] cat
/etc/condor-ce/mapfiles.d/11_99_token-mapping_DEBUG.conf
SCITOKENS
/^https:\/\/wlcg\.cloud\.cnaf\.infn\.it\/,8ec82f26\-a407\-44d7\-aa32\-19cd985cd2d1$/
desyusr009
SCITOKENS
/^https:\/\/wlcg\.cloud\.cnaf\.infn\.it\/,1ec796cb\-250b\-479d\-a9e9\-6509995adab0$/
desyusr007
# SCITOKENS
/^https:\/\/wlcg\.cloud\.cnaf\.infn\.it\/,bf47638b-5be1-4cda-a156-c2b9d2d1d352$/
desyusr009
# SCITOKENS
/^https:\/\/wlcg\.cloud\.cnaf\.infn\.it\/,bc2de59f-c564-4fef-9614-d89c1819426b$/
desyusr009
SCITOKENS
/^https:\/\/wlcg\.cloud\.cnaf\.infn\.it\/,737b9ec0\-fb66\-472d\-9ce3\-e943a677464f$/
desyusr008
# SCITOKENS /^https\:\/\/.*,.*/ desyprd004
On 14/04/2023 22.36, Jaime Frey via HTCondor-users wrote:
Can you add the D_SECURITY logging level on the CE daemons? Many
SciTokens-related errors are not recorded otherwise.
 - Jaime
On Apr 14, 2023, at 9:20 AM, Thomas Hartmann
<thomas.hartmann@xxxxxxx> wrote:
Hi all,
preparing the migration from CondorCE 5 to GSI-less 6, we noticed
that the WLCGToken mapping has been failing for some time.
Cross-checking on our production v5 CEs, we realized, that token
mapping has been failing for some time and that authz fall back to
GSI, which had been unnoticed so far.
Since token authz had worked in the past, I am currently struggling
to identify, what change or config broke the mapping.
Starting with a fresh CondorCE installation from scratch and adding
configs & mappings, I have not been able to get the token mapping
working again.
It is a CondorCE v6, Condor v10.4 installation on EL7 [1].
Mapping rules are tokens only with a test client mapped to (existing)
local users [2], so that tokens like [3] should get mapped onto the
local `desyusr007`.
However, trace and write pings always fail due to an allegedly broken
mapping [4]. Judging from the SchedLog and AuditLog [5,6] the tokens
are received and parsed - but then something(??) is not to the CE's
liking :-/
Submitting a job to a friendly site's CE works with the mapping rule
as of [2] deployed - so I would rule out an issue with the
client/tokens. The other way round, a job from the remote site
(running under a token from a client of the other site) fails, so
that it is most probable something local with my CE.
Also a very trusting catch all map rule
 SCITOKENS /^https\:\/\/.*,.*/ desyprd004
failed.
Daemon output is already on `ALL_DEBUG = D_FULLDEBUG` but maybe there
is a way to increase the audit logging to get an idea, why the
matching fails?
SELinux or so seems not involved so far.
Maybe someone has an idea, where I might find the underlying issue?
(probably something system related and not directly CondorCE config
specific??).
Cheers and thanks for any idea,
 Thomas
[1]
condor-procd-10.4.0-1.el7.x86_64
condor-classads-10.4.0-1.el7.x86_64
python2-condor-10.4.0-1.el7.x86_64
htcondor-ce-6.0.0-1.el7.noarch
condor-stash-plugin-6.10.0-1.x86_64
python3-condor-10.4.0-1.el7.x86_64
htcondor-ce-client-6.0.0-1.el7.noarch
condor-externals-9.0.15-1.el7.x86_64
condor-10.4.0-1.el7.x86_64
condor-blahp-10.4.0-1.el7.x86_64
htcondor-ce-apel-6.0.0-1.el7.noarch
htcondor-release-10.x-1.el7.noarch
[2]
grep include /etc/condor-ce/condor_mapfile
@include /etc/condor-ce/mapfiles.d/
@include /usr/share/condor-ce/mapfiles.d/
cat /etc/condor-ce/mapfiles.d/11_99_token-mapping_DEBUG.conf
SCITOKENS
/^https:\/\/wlcg\.cloud\.cnaf\.infn\.it\/,8ec82f26\-a407\-44d7\-aa32\-19cd985cd2d1$/ desyusr009
SCITOKENS
/^https:\/\/wlcg\.cloud\.cnaf\.infn\.it\/,1ec796cb\-250b\-479d\-a9e9\-6509995adab0$/ desyusr007
# SCITOKENS
/^https:\/\/wlcg\.cloud\.cnaf\.infn\.it\/,bf47638b-5be1-4cda-a156-c2b9d2d1d352$/ desyusr009
# SCITOKENS
/^https:\/\/wlcg\.cloud\.cnaf\.infn\.it\/,bc2de59f-c564-4fef-9614-d89c1819426b$/ desyusr009
SCITOKENS
/^https:\/\/wlcg\.cloud\.cnaf\.infn\.it\/,737b9ec0\-fb66\-472d\-9ce3\-e943a677464f$/ desyusr008
[3]
{
 "wlcg.ver": "1.0",
 "sub": "1ec796cb-250b-479d-a9e9-6509995adab0",
 "aud": "https://wlcg.cern.ch/jwt/v1/any";,
 "nbf": 1681479491,
 "scope": "openid compute.create offline_access compute.read
compute.cancel compute.modify",
 "iss": "https://wlcg.cloud.cnaf.infn.it/";,
 "exp": 1681483091,
 "iat": 1681479491,
 "jti": "78d1ad5a-2be0-4367-88bb-6a9f59939bc5",
 "client_id": "8ec82f26-a407-44d7-aa32-19cd985cd2d1"
}
[4]
export _condor_SEC_CLIENT_AUTHENTICATION_METHODS=SCITOKENS
export BEARER_TOKEN_FILE=/tmp/token_$(id -u)
date; oidc-token -f --time=720 belle-desydebug-group >
/tmp/token_$(id -u); condor_ce_trace --debug
grid-htcondorce-dev.desy.de
Fri Apr 14 15:46:32 CEST 2023
...
04/14/23 15:46:32 SharedPortClient: sent connection request to daemon
at <131.169.223.131:9619> for shared port id schedd_1298351_f7d0
04/14/23 15:46:32 Looking for token in file /tmp/token_14053
04/14/23 15:46:37 SECMAN: required authentication with daemon at
<131.169.223.131:9619> failed, so aborting command DC_SEC_QUERY.
********************************************************************************
2023-04-14 15:46:41 ERROR: WRITE access failed for scheduler daemon at
<131.169.223.131:9619?addrs=131.169.223.131-9619+[2001-638-700-10df--
1-83]-9619&alias=grid-htcondorce-dev.desy.de&noUDP&sock=schedd_1298351_f7d0>.
WRITE failed!
AUTHENTICATE:1003:Failed to authenticate with any method
AUTHENTICATE:1004:Failed to authenticate using SCITOKENS
********************************************************************************
[5]
04/14/23 15:46:32 Examining SciToken with payload
{"wlcg.ver":"1.0","sub":"1ec796cb-250b-479d-a9e9-6509995adab0","aud":"https:\/\/wlcg.cern.ch\/jwt\/v1\/any","nbf":1681479491,"scope":"openid compute.create offline_access compute.read compute.cancel compute.modify","iss":"https:\/\/wlcg.cloud.cnaf.infn.it\/","exp":1681483091,"iat":1681479491,"jti":"78d1ad5a-2be0-4367-88bb-6a9f59939bc5","client_id":"8ec82f26-a407-44d7-aa32-19cd985cd2d1"}.
04/14/23 15:46:37 DC_AUTHENTICATE: required authentication of
131.169.223.90 failed: AUTHENTICATE:1003:Failed to authenticate with
any method|AUTHENTICATE:1004:Failed to authenticate using SCITOKENS
04/14/23 15:46:37 Examining SciToken with payload
{"wlcg.ver":"1.0","sub":"1ec796cb-250b-479d-a9e9-6509995adab0","aud":"https:\/\/wlcg.cern.ch\/jwt\/v1\/any","nbf":1681479491,"scope":"openid compute.create offline_access compute.read compute.cancel compute.modify","iss":"https:\/\/wlcg.cloud.cnaf.infn.it\/","exp":1681483091,"iat":1681479491,"jti":"78d1ad5a-2be0-4367-88bb-6a9f59939bc5","client_id":"8ec82f26-a407-44d7-aa32-19cd985cd2d1"}.
04/14/23 15:46:41 DC_AUTHENTICATE: required authentication of
131.169.223.90 failed: AUTHENTICATE:1003:Failed to authenticate with
any method|AUTHENTICATE:1004:Failed to authenticate using SCITOKENS
04/14/23 15:46:49 Evaluated periodic expressions in 0.000s,
scheduling next run in 61s
[6]
04/14/23 15:46:32 (cid:21) Examining SciToken with payload
{"wlcg.ver":"1.0","sub":"1ec796cb-250b-479d-a9e9-6509995adab0","aud":"https:\/\/wlcg.cern.ch\/jwt\/v1\/any","nbf":1681479491,"scope":"openid compute.create offline_access compute.read compute.cancel compute.modify","iss":"https:\/\/wlcg.cloud.cnaf.infn.it\/","exp":1681483091,"iat":1681479491,"jti":"78d1ad5a-2be0-4367-88bb-6a9f59939bc5","client_id":"8ec82f26-a407-44d7-aa32-19cd985cd2d1"}.
04/14/23 15:46:37 (cid:23) Examining SciToken with payload
{"wlcg.ver":"1.0","sub":"1ec796cb-250b-479d-a9e9-6509995adab0","aud":"https:\/\/wlcg.cern.ch\/jwt\/v1\/any","nbf":1681479491,"scope":"openid compute.create offline_access compute.read compute.cancel compute.modify","iss":"https:\/\/wlcg.cloud.cnaf.infn.it\/","exp":1681483091,"iat":1681479491,"jti":"78d1ad5a-2be0-4367-88bb-6a9f59939bc5","client_id":"8ec82f26-a407-44d7-aa32-19cd985cd2d1"}.
_______________________________________________
HTCondor-users mailing list
To unsubscribe, send a message to htcondor-users-request@xxxxxxxxxxx
with a
subject: Unsubscribe
You can also unsubscribe by visiting
https://lists.cs.wisc.edu/mailman/listinfo/htcondor-users
The archives can be found at:
https://lists.cs.wisc.edu/archive/htcondor-users/
_______________________________________________
HTCondor-users mailing list
To unsubscribe, send a message to htcondor-users-request@xxxxxxxxxxx
with a
subject: Unsubscribe
You can also unsubscribe by visiting
https://lists.cs.wisc.edu/mailman/listinfo/htcondor-users
The archives can be found at:
https://lists.cs.wisc.edu/archive/htcondor-users/
grid@grid-mon0: [~] export BEARER_TOKEN_FILE=/tmp/token_$(id -u)
grid@grid-mon0: [~] oidc-token -f --time=720 belle-desydebug-group > ${BEARER_TOKEN_FILE} ; cat ${BEARER_TOKEN_FILE} | cut -d "." -f 2 | base64 -d 2>/dev/null | jq ; condor_ce_trace --debug grid-htcondorce-dev02.desy.de
{
"wlcg.ver": "1.0",
"sub": "1ec796cb-250b-479d-a9e9-6509995adab0",
"aud": "https://wlcg.cern.ch/jwt/v1/any";,
"nbf": 1681813453,
"scope": "openid compute.create offline_access compute.read compute.cancel compute.modify",
"iss": "https://wlcg.cloud.cnaf.infn.it/";,
"exp": 1681817053,
"iat": 1681813453,
"jti": "74a54596-97c8-4fb8-9305-214cd7b2a04a",
"client_id": "8ec82f26-a407-44d7-aa32-19cd985cd2d1"
}
04/18/23 12:24:13 Result of reading /etc/issue: \S
04/18/23 12:24:13 Result of reading /etc/redhat-release: CentOS Linux release 7.9.2009 (Core)
04/18/23 12:24:13 Using IDs: 4 processors, 4 CPUs, 0 HTs
04/18/23 12:24:13 Enumerating interfaces: lo 127.0.0.1 up
04/18/23 12:24:13 Enumerating interfaces: eth0 131.169.223.90 up
04/18/23 12:24:13 Enumerating interfaces: lo ::1 up
04/18/23 12:24:13 Enumerating interfaces: eth0 2001:638:700:10df::1:5a up
04/18/23 12:24:13 Enumerating interfaces: eth0 fe80::11:69ff:fe22:3090 up
04/18/23 12:24:13 Will use TCP to update collector grid-htcondorce-dev02.desy.de <131.169.223.197:9619?alias=grid-htcondorce-dev02.desy.de>
04/18/23 12:24:13 Trying to query collector <131.169.223.197:9619?alias=grid-htcondorce-dev02.desy.de>
04/18/23 12:24:13 Trying to query collector <131.169.223.197:9619?alias=grid-htcondorce-dev02.desy.de>
Testing HTCondor-CE authorization...
04/18/23 12:24:13 SharedPortClient: sent connection request to daemon at <131.169.223.197:9619> for shared port id collector
Verified READ access for collector daemon at <131.169.223.197:9619?addrs=131.169.223.197-9619+[2001-638-700-10df--1-c5]-9619&alias=grid-htcondorce-dev02.desy.de&noUDP&sock=collector>
***** Ping response ClassAd *****
[
RemoteVersion = "$CondorVersion: 9.0.15 Jul 20 2022 BuildID: 597761 PackageID: 9.0.15-1 $";
MyRemoteUserName = "unauthenticated@unmapped";
UseSession = "YES";
AuthCommand = 60020;
Sid = "grid-htcondorce-dev02:24331:1681813453:2569";
Enact = "YES";
IssuerKeys = "POOL";
ValidCommands = "60007,457,60020,68,5,6,7,9,12,43,20,46,78,50,56,48,71,74";
OutgoingNegotiation = "PREFERRED";
SessionDuration = "60";
Command = 60040;
AuthMethodsList = "SCITOKENS";
SessionLease = 3600;
TrustDomain = "grid-htcondorce-dev02.desy.de:9619";
AuthMethods = "SCITOKENS";
Subsystem = "TOOL";
Authentication = "NO";
Integrity = "NO";
User = "unauthenticated@unmapped";
Encryption = "NO";
TrackState = true;
CryptoMethodsList = "AES,BLOWFISH,3DES";
AuthorizationSucceeded = true;
ConnectSinful = "<131.169.223.197:9619?addrs=131.169.223.197-9619+[2001-638-700-10df--1-c5]-9619&alias=grid-htcondorce-dev02.desy.de&noUDP&sock=collector>"
]
********************
04/18/23 12:24:13 SharedPortClient: sent connection request to daemon at <131.169.223.197:9619> for shared port id schedd_24264_dce4
04/18/23 12:24:13 Looking for token in file /tmp/token_14053
04/18/23 12:24:18 SECMAN: required authentication with daemon at <131.169.223.197:9619> failed, so aborting command DC_SEC_QUERY.
********************************************************************************
2023-04-18 12:24:22 ERROR: WRITE access failed for scheduler daemon at
<131.169.223.197:9619?addrs=131.169.223.197-9619+[2001-638-700-10df--
1-c5]-9619&alias=grid-htcondorce-dev02.desy.de&noUDP&sock=schedd_24264_dce4>.
WRITE failed!
AUTHENTICATE:1003:Failed to authenticate with any method
AUTHENTICATE:1004:Failed to authenticate using SCITOKENS
********************************************************************************
04/18/23 12:24:13.793 (D_COMMAND) Calling Handler <SharedPortEndpoint::HandleListenerAccept> (0)
04/18/23 12:24:13.793 (D_SECURITY) DC_AUTHENTICATE: received DC_AUTHENTICATE from <131.169.223.90:39993>
04/18/23 12:24:13.793 (D_SECURITY) DC_AUTHENTICATE: received following ClassAd:
AuthCommand = 60021
AuthMethods = "SCITOKENS"
Authentication = "OPTIONAL"
Command = 60040
ConnectSinful = "<131.169.223.197:9619?addrs=131.169.223.197-9619+[2001-638-700-10df--1-c5]-9619&alias=grid-htcondorce-dev02.desy.de&noUDP&sock=schedd_24264_dce4>"
CryptoMethods = "AES,BLOWFISH,3DES"
Enact = "NO"
Encryption = "OPTIONAL"
Integrity = "OPTIONAL"
NewSession = "YES"
OutgoingNegotiation = "PREFERRED"
RemoteVersion = "$CondorVersion: 9.0.17 Sep 29 2022 BuildID: 607845 PackageID: 9.0.17-1 $"
ServerPid = 27694
SessionDuration = "60"
SessionLease = 3600
Subsystem = "TOOL"
TrustDomain = "grid-mon0.desy.de:9619"
04/18/23 12:24:13.793 (D_SECURITY) DC_AUTHENTICATE: our_policy:
AuthMethods = "FS,TOKEN,SCITOKENS,GSI,SSL"
Authentication = "REQUIRED"
CryptoMethods = "AES,BLOWFISH,3DES"
Enact = "NO"
Encryption = "OPTIONAL"
Integrity = "REQUIRED"
IssuerKeys = "POOL"
OutgoingNegotiation = "REQUIRED"
ParentUniqueID = "grid-htcondorce-dev02:24264:1681746325"
ServerPid = 24333
SessionDuration = "86400"
SessionLease = 3600
Subsystem = "SCHEDD"
TrustDomain = "grid-htcondorce-dev02.desy.de:9619"
04/18/23 12:24:13.793 (D_SECURITY) DC_AUTHENTICATE: the_policy:
AuthMethods = "SCITOKENS"
AuthMethodsList = "SCITOKENS"
Authentication = "YES"
CryptoMethods = "AES,BLOWFISH,3DES"
CryptoMethodsList = "AES,BLOWFISH,3DES"
Enact = "YES"
Encryption = "YES"
Integrity = "YES"
IssuerKeys = "POOL"
SessionDuration = "60"
SessionLease = 3600
TrustDomain = "grid-htcondorce-dev02.desy.de:9619"
04/18/23 12:24:13.794 (D_SECURITY) DC_AUTHENTICATE: generating AES-GCM key for session grid-htcondorce-dev02:24333:1681813453:2567...
04/18/23 12:24:13.794 (D_SECURITY) SECMAN: Sending following response ClassAd:
AuthMethods = "SCITOKENS"
AuthMethodsList = "SCITOKENS"
Authentication = "YES"
CryptoMethods = "AES"
CryptoMethodsList = "AES,BLOWFISH,3DES"
Enact = "YES"
Encryption = "YES"
Integrity = "YES"
IssuerKeys = "POOL"
RemoteVersion = "$CondorVersion: 9.0.15 Jul 20 2022 BuildID: 597761 PackageID: 9.0.15-1 $"
SessionDuration = "60"
SessionLease = 3600
TrustDomain = "grid-htcondorce-dev02.desy.de:9619"
04/18/23 12:24:13.794 (D_SECURITY) SECMAN: new session, doing initial authentication.
04/18/23 12:24:13.794 (D_SECURITY) Returning to DC while we wait for socket to authenticate.
04/18/23 12:24:13.794 (D_COMMAND) Return from Handler <SharedPortEndpoint::HandleListenerAccept> 0.000629s
04/18/23 12:24:13.798 (D_COMMAND) Calling Handler <DaemonCommandProtocol::WaitForSocketData> (5)
04/18/23 12:24:13.798 (D_SECURITY) DC_AUTHENTICATE: authenticating RIGHT NOW.
04/18/23 12:24:13.798 (D_SECURITY) AUTHENTICATE: setting timeout for (unknown) to 20.
04/18/23 12:24:13.798 (D_SECURITY) AUTHENTICATE: in authenticate( addr == '(unknown)', methods == 'SCITOKENS')
04/18/23 12:24:13.798 (D_SECURITY) AUTHENTICATE: can still try these methods: SCITOKENS
04/18/23 12:24:13.798 (D_SECURITY) HANDSHAKE: in handshake(my_methods = 'SCITOKENS')
04/18/23 12:24:13.798 (D_SECURITY) HANDSHAKE: handshake() - i am the server
04/18/23 12:24:13.798 (D_SECURITY) HANDSHAKE: client sent (methods == 4096)
04/18/23 12:24:13.798 (D_SECURITY) HANDSHAKE: i picked (method == 4096)
04/18/23 12:24:13.798 (D_SECURITY) HANDSHAKE: client received (method == 4096)
04/18/23 12:24:13.798 (D_SECURITY) AUTHENTICATE: will try to use 4096 (SCITOKENS)
04/18/23 12:24:13.798 (D_SECURITY) AUTHENTICATE: do_authenticate is 1.
04/18/23 12:24:13.798 (D_SECURITY) CADIR: '/etc/grid-security/certificates'
04/18/23 12:24:13.798 (D_SECURITY) CERTFILE: '/etc/grid-security/hostcert.pem'
04/18/23 12:24:13.798 (D_SECURITY) KEYFILE: '/etc/grid-security/hostkey.pem'
04/18/23 12:24:13.798 (D_SECURITY) CIPHERLIST: 'ECDHE-ECDSA-CHACHA20-POLY1305:ECDHE-RSA-CHACHA20-POLY1305:ECDHE-ECDSA-AES128-GCM-SHA256:ECDHE-RSA-AES128-GCM-SHA256:ECDHE-ECDSA-AES256-GCM-SHA384:ECDHE-RSA-AES256-GCM-SHA384:DHE-RSA-AES128-GCM-SHA256:DHE-RSA-AES256-GCM-SHA384:ECDHE-ECDSA-AES128-SHA256:ECDHE-RSA-AES128-SHA256:ECDHE-ECDSA-AES128-SHA:ECDHE-RSA-AES256-SHA384:ECDHE-RSA-AES128-SHA:ECDHE-ECDSA-AES256-SHA384:ECDHE-ECDSA-AES256-SHA:ECDHE-RSA-AES256-SHA:DHE-RSA-AES128-SHA256:DHE-RSA-AES128-SHA:DHE-RSA-AES256-SHA256:DHE-RSA-AES256-SHA:ECDHE-ECDSA-DES-CBC3-SHA:ECDHE-RSA-DES-CBC3-SHA:EDH-RSA-DES-CBC3-SHA:AES128-GCM-SHA256:AES256-GCM-SHA384:AES128-SHA256:AES256-SHA256:AES128-SHA:AES256-SHA:DES-CBC3-SHA:!DSS'
04/18/23 12:24:13.799 (D_SECURITY) Will return to DC because authentication is incomplete.
04/18/23 12:24:13.799 (D_COMMAND) Return from Handler <DaemonCommandProtocol::WaitForSocketData> 0.001070s
04/18/23 12:24:13.811 (D_COMMAND) Calling Handler <DaemonCommandProtocol::WaitForSocketData> (5)
04/18/23 12:24:13.812 (D_SECURITY) SSL Auth: Trying to accept.
04/18/23 12:24:13.812 (D_SECURITY) Accept returned -1.
04/18/23 12:24:13.812 (D_SECURITY) SSL Auth: SSL: trying to continue reading.
04/18/23 12:24:13.812 (D_SECURITY) Round 0.
04/18/23 12:24:13.812 (D_SECURITY) SSL Auth: Receive message.
04/18/23 12:24:13.812 (D_SECURITY) Received message (2).
04/18/23 12:24:13.812 (D_SECURITY) Status (c: 2, s: 2)
04/18/23 12:24:13.812 (D_SECURITY) SSL Auth: Trying to accept.
04/18/23 12:24:13.812 (D_SECURITY) Accept returned -1.
04/18/23 12:24:13.812 (D_SECURITY) SSL Auth: SSL: trying to continue reading.
04/18/23 12:24:13.812 (D_SECURITY) Round 1.
04/18/23 12:24:13.812 (D_SECURITY) Send message (2).
04/18/23 12:24:13.812 (D_SECURITY) Status (c: 2, s: 2)
04/18/23 12:24:13.812 (D_SECURITY) SSL Auth: Trying to accept.
04/18/23 12:24:13.812 (D_SECURITY) Accept returned -1.
04/18/23 12:24:13.812 (D_SECURITY) SSL Auth: SSL: trying to continue reading.
04/18/23 12:24:13.812 (D_SECURITY) Round 2.
04/18/23 12:24:13.812 (D_SECURITY) SSL Auth: Would block when trying to receive message
04/18/23 12:24:13.812 (D_SECURITY) AUTHENTICATE: auth would still block
04/18/23 12:24:13.812 (D_SECURITY) Will return to DC to continue authentication..
04/18/23 12:24:13.812 (D_COMMAND) Return from Handler <DaemonCommandProtocol::WaitForSocketData> 0.000441s
04/18/23 12:24:13.814 (D_COMMAND) Calling Handler <DaemonCommandProtocol::WaitForSocketData> (5)
04/18/23 12:24:13.814 (D_SECURITY) SSL Auth: Trying to accept.
04/18/23 12:24:13.814 (D_SECURITY) Accept returned -1.
04/18/23 12:24:13.814 (D_SECURITY) SSL Auth: SSL: trying to continue reading.
04/18/23 12:24:13.814 (D_SECURITY) Round 2.
04/18/23 12:24:13.814 (D_SECURITY) SSL Auth: Receive message.
04/18/23 12:24:13.814 (D_SECURITY) Received message (2).
04/18/23 12:24:13.814 (D_SECURITY) Status (c: 2, s: 2)
04/18/23 12:24:13.814 (D_SECURITY) SSL Auth: Trying to accept.
04/18/23 12:24:13.821 (D_SECURITY) Accept returned 1.
04/18/23 12:24:13.821 (D_SECURITY) Round 3.
04/18/23 12:24:13.821 (D_SECURITY) Send message (4).
04/18/23 12:24:13.821 (D_SECURITY) Status (c: 2, s: 4)
04/18/23 12:24:13.821 (D_SECURITY) Round 4.
04/18/23 12:24:13.821 (D_SECURITY) SSL Auth: Would block when trying to receive message
04/18/23 12:24:13.821 (D_SECURITY) AUTHENTICATE: auth would still block
04/18/23 12:24:13.821 (D_SECURITY) Will return to DC to continue authentication..
04/18/23 12:24:13.821 (D_COMMAND) Return from Handler <DaemonCommandProtocol::WaitForSocketData> 0.007527s
04/18/23 12:24:13.822 (D_COMMAND) Calling Handler <DaemonCommandProtocol::WaitForSocketData> (5)
04/18/23 12:24:13.822 (D_SECURITY) Round 4.
04/18/23 12:24:13.822 (D_SECURITY) SSL Auth: Receive message.
04/18/23 12:24:13.822 (D_SECURITY) Received message (4).
04/18/23 12:24:13.822 (D_SECURITY) Status (c: 4, s: 4)
04/18/23 12:24:13.822 (D_SECURITY) SSL Auth: Server trying post connection check.
04/18/23 12:24:13.822 (D_SECURITY) SSL Auth: post_connection_check.
04/18/23 12:24:13.822 (D_SECURITY) SSL Auth: Anonymous client is allowed; not checking.
04/18/23 12:24:13.822 (D_SECURITY) Writing round 0.
04/18/23 12:24:13.822 (D_SECURITY) SSL write has succeeded.
04/18/23 12:24:13.822 (D_SECURITY) Send message (4).
04/18/23 12:24:13.822 (D_SECURITY) Status: c: 2, s: 4
04/18/23 12:24:13.822 (D_SECURITY) Writing round 1.
04/18/23 12:24:13.822 (D_SECURITY) SSL write has succeeded.
04/18/23 12:24:13.822 (D_SECURITY) SSL Auth: Would block when trying to receive message
04/18/23 12:24:13.822 (D_SECURITY) AUTHENTICATE: auth would still block
04/18/23 12:24:13.822 (D_SECURITY) Will return to DC to continue authentication..
04/18/23 12:24:13.822 (D_COMMAND) Return from Handler <DaemonCommandProtocol::WaitForSocketData> 0.000204s
04/18/23 12:24:13.822 (D_COMMAND) Calling Handler <DaemonCommandProtocol::WaitForSocketData> (5)
04/18/23 12:24:13.822 (D_SECURITY) Writing round 1.
04/18/23 12:24:13.822 (D_SECURITY) SSL write has succeeded.
04/18/23 12:24:13.822 (D_SECURITY) SSL Auth: Receive message.
04/18/23 12:24:13.822 (D_SECURITY) Received message (4).
04/18/23 12:24:13.822 (D_SECURITY) Status: c: 4, s: 4
04/18/23 12:24:13.822 (D_SECURITY:2) CRYPTO: simple reset m_ivec(len 8) and m_num
04/18/23 12:24:13.822 (D_SECURITY) Reading SciTokens round 0.
04/18/23 12:24:13.822 (D_SECURITY) SSL Auth: SciToken: continue read/write.
04/18/23 12:24:13.822 (D_SECURITY) SSL Auth: Receive message.
04/18/23 12:24:13.822 (D_SECURITY) Received message (4).
04/18/23 12:24:13.822 (D_SECURITY) SciToken exchange server status: c: 4, s: 2
04/18/23 12:24:13.822 (D_SECURITY) Reading SciTokens round 1.
04/18/23 12:24:13.822 (D_SECURITY:2) Peeked at the sent token; 730 bytes long; SSL status 4.
04/18/23 12:24:13.822 (D_SECURITY) SciToken SSL read is successful.
04/18/23 12:24:18.236 (D_SECURITY) SCITOKENS:2:Failed to verify token and generate ACLs: Timeout was reached
04/18/23 12:24:18.236 (D_SECURITY:2) AUTHENTICATION: map file already loaded.
04/18/23 12:24:18.236 (D_ERROR) Failed to map SCITOKENS authenticated identity '', failing authentication to give another authentication method a go.
04/18/23 12:24:18.236 (D_SECURITY) Send message (3).
04/18/23 12:24:18.236 (D_SECURITY) SciToken exchange server status: c: 4, s: 3
04/18/23 12:24:18.236 (D_SECURITY) SSL Auth: SciToken Authentication failed at token exchange.
04/18/23 12:24:18.237 (D_SECURITY) AUTHENTICATE: do_authenticate is 0.
04/18/23 12:24:18.237 (D_SECURITY) AUTHENTICATE: method 4096 (SCITOKENS) failed.
04/18/23 12:24:18.237 (D_SECURITY) AUTHENTICATE: can still try these methods: SCITOKENS
04/18/23 12:24:18.237 (D_SECURITY) HANDSHAKE: in handshake(my_methods = 'SCITOKENS')
04/18/23 12:24:18.237 (D_SECURITY) AUTHENTICATE: handshake would block
04/18/23 12:24:18.237 (D_SECURITY) Will return to DC to continue authentication..
04/18/23 12:24:18.237 (D_COMMAND) Return from Handler <DaemonCommandProtocol::WaitForSocketData> 4.414264s
04/18/23 12:24:18.237 (D_COMMAND) Calling Handler <SharedPortEndpoint::HandleListenerAccept> (0)
04/18/23 12:24:18.237 (D_SECURITY) DC_AUTHENTICATE: received DC_AUTHENTICATE from <131.169.223.119:1773>
04/18/23 12:24:18.237 (D_SECURITY) DC_AUTHENTICATE: received following ClassAd:
AuthCommand = 60020
AuthMethods = "FS,TOKEN,KERBEROS,GSI,SCITOKENS,SSL,CLAIMTOBE"
Authentication = "OPTIONAL"
Command = 60040
ConnectSinful = "<131.169.223.197:9619?addrs=131.169.223.197-9619+[2001-638-700-10df--1-c5]-9619&alias=grid-htcondorce-dev02.desy.de&noUDP&sock=schedd_24264_dce4>"
CryptoMethods = "AES,BLOWFISH,3DES"
Enact = "NO"
Encryption = "OPTIONAL"
Integrity = "OPTIONAL"
NewSession = "YES"
OutgoingNegotiation = "PREFERRED"
RemoteVersion = "$CondorVersion: 9.0.15 Jul 20 2022 BuildID: 597761 PackageID: 9.0.15-1 $"
ServerPid = 2525633
SessionDuration = "60"
SessionLease = 3600
Subsystem = "TOOL"
TrustDomain = "condor01.desy.de"
04/18/23 12:24:18.237 (D_SECURITY:2) Filtering authentication methods (FS,TOKEN,SCITOKENS,GSI,SSL) prior to offering them remotely.
04/18/23 12:24:18.237 (D_SECURITY:2) Can try token auth because we have at least one named credential.
04/18/23 12:24:18.237 (D_SECURITY:2) Will try IDTOKENS auth.
04/18/23 12:24:18.237 (D_SECURITY) Inserting pre-auth metadata for TOKEN.
04/18/23 12:24:18.237 (D_SECURITY) DC_AUTHENTICATE: our_policy:
AuthMethods = "FS,TOKEN,SCITOKENS,GSI,SSL"
Authentication = "OPTIONAL"
CryptoMethods = "AES,BLOWFISH,3DES"
Enact = "NO"
Encryption = "OPTIONAL"
Integrity = "OPTIONAL"
IssuerKeys = "POOL"
OutgoingNegotiation = "PREFERRED"
ParentUniqueID = "grid-htcondorce-dev02:24264:1681746325"
ServerPid = 24333
SessionDuration = "86400"
SessionLease = 3600
Subsystem = "SCHEDD"
TrustDomain = "grid-htcondorce-dev02.desy.de:9619"
04/18/23 12:24:18.237 (D_SECURITY) DC_AUTHENTICATE: the_policy:
AuthMethods = "FS"
AuthMethodsList = "FS,TOKEN,SCITOKENS,GSI,SSL"
Authentication = "NO"
CryptoMethods = "AES,BLOWFISH,3DES"
CryptoMethodsList = "AES,BLOWFISH,3DES"
Enact = "YES"
Encryption = "NO"
Integrity = "NO"
IssuerKeys = "POOL"
SessionDuration = "60"
SessionLease = 3600
TrustDomain = "grid-htcondorce-dev02.desy.de:9619"
04/18/23 12:24:18.237 (D_SECURITY) SECMAN: Sending following response ClassAd:
AuthMethods = "FS"
AuthMethodsList = "FS,TOKEN,SCITOKENS,GSI,SSL"
Authentication = "NO"
CryptoMethodsList = "AES,BLOWFISH,3DES"
Enact = "YES"
Encryption = "NO"
Integrity = "NO"
IssuerKeys = "POOL"
RemoteVersion = "$CondorVersion: 9.0.15 Jul 20 2022 BuildID: 597761 PackageID: 9.0.15-1 $"
SessionDuration = "60"
SessionLease = 3600
TrustDomain = "grid-htcondorce-dev02.desy.de:9619"
04/18/23 12:24:18.237 (D_SECURITY) DC_AUTHENTICATE: not authenticating.
04/18/23 12:24:18.237 (D_SECURITY) DC_AUTHENTICATE: Success.
04/18/23 12:24:18.237 (D_ALWAYS) PERMISSION GRANTED to unauthenticated@unmapped from host 131.169.223.119 for command 60020 (DC_NOP_READ), access level READ: reason: READ authorization policy allows access by anyone
04/18/23 12:24:18.237 (D_SECURITY) DC_AUTHENTICATE: sending session ad:
ReturnCode = "AUTHORIZED"
Sid = "grid-htcondorce-dev02:24333:1681813458:2568"
User = "unauthenticated@unmapped"
ValidCommands = "60007,457,60020,443,441,6,12,5,515,516,1111,471"
04/18/23 12:24:18.238 (D_SECURITY) DC_AUTHENTICATE: sent session grid-htcondorce-dev02:24333:1681813458:2568 info!
04/18/23 12:24:18.238 (D_SECURITY:2) SESSION: fallback crypto method would be BLOWFISH.
04/18/23 12:24:18.238 (D_SECURITY:2) SESSION: server checking key type: -1
04/18/23 12:24:18.238 (D_SECURITY) DC_AUTHENTICATE: added incoming session id grid-htcondorce-dev02:24333:1681813458:2568 to cache for 80 seconds (lease is 3620s, return address is unknown).
AuthMethods = "FS"
AuthMethodsList = "FS,TOKEN,SCITOKENS,GSI,SSL"
Authentication = "NO"
CryptoMethodsList = "AES,BLOWFISH,3DES"
Enact = "YES"
Encryption = "NO"
Integrity = "NO"
IssuerKeys = "POOL"
RemoteVersion = "$CondorVersion: 9.0.15 Jul 20 2022 BuildID: 597761 PackageID: 9.0.15-1 $"
ServerPid = 2525633
SessionDuration = "60"
SessionLease = 3600
Sid = "grid-htcondorce-dev02:24333:1681813458:2568"
Subsystem = "TOOL"
TrustDomain = "grid-htcondorce-dev02.desy.de:9619"
User = "unauthenticated@unmapped"
ValidCommands = "60007,457,60020,443,441,6,12,5,515,516,1111,471"
04/18/23 12:24:18.238 (D_ALWAYS) SECMAN: Succesfully sent DC_SEC_QUERY classad to <131.169.223.119:1773>!
AuthorizationSucceeded = true
04/18/23 12:24:18.238 (D_COMMAND) Return from Handler <SharedPortEndpoint::HandleListenerAccept> 0.000997s
04/18/23 12:24:18.239 (D_COMMAND) Calling Handler <DaemonCommandProtocol::WaitForSocketData> (5)
04/18/23 12:24:18.239 (D_SECURITY) HANDSHAKE: handshake() - i am the server
04/18/23 12:24:18.239 (D_SECURITY) HANDSHAKE: client sent (methods == 0)
04/18/23 12:24:18.239 (D_SECURITY) HANDSHAKE: i picked (method == 0)
04/18/23 12:24:18.239 (D_SECURITY) HANDSHAKE: client received (method == 0)
04/18/23 12:24:18.239 (D_SECURITY) AUTHENTICATE: can still try these methods: SCITOKENS
04/18/23 12:24:18.239 (D_SECURITY:2) AUTHENTICATE: no available authentication methods succeeded!
04/18/23 12:24:18.239 (D_ALWAYS) DC_AUTHENTICATE: required authentication of 131.169.223.90 failed: AUTHENTICATE:1003:Failed to authenticate with any method|AUTHENTICATE:1004:Failed to authenticate using SCITOKENS
04/18/23 12:24:18.239 (D_COMMAND) Return from Handler <DaemonCommandProtocol::WaitForSocketData> 0.000187s
04/18/23 12:24:18.256 (D_COMMAND) Calling Handler <SharedPortEndpoint::HandleListenerAccept> (0)
04/18/23 12:24:18.257 (D_SECURITY) DC_AUTHENTICATE: received DC_AUTHENTICATE from <131.169.223.90:39788>
04/18/23 12:24:18.257 (D_SECURITY) DC_AUTHENTICATE: received following ClassAd:
AuthCommand = 60021
AuthMethods = "SCITOKENS"
Authentication = "OPTIONAL"
Command = 60040
ConnectSinful = "<131.169.223.197:9619?addrs=131.169.223.197-9619+[2001-638-700-10df--1-c5]-9619&alias=grid-htcondorce-dev02.desy.de&noUDP&sock=schedd_24264_dce4>"
CryptoMethods = "AES,BLOWFISH,3DES"
Enact = "NO"
Encryption = "OPTIONAL"
Integrity = "OPTIONAL"
NewSession = "YES"
OutgoingNegotiation = "PREFERRED"
RemoteVersion = "$CondorVersion: 9.0.17 Sep 29 2022 BuildID: 607845 PackageID: 9.0.17-1 $"
ServerPid = 28067
SessionDuration = "60"
SessionLease = 3600
Subsystem = "TOOL"
TrustDomain = "grid-mon0.desy.de:9619"
04/18/23 12:24:18.257 (D_SECURITY:2) Filtering authentication methods (FS,TOKEN,SCITOKENS,GSI,SSL) prior to offering them remotely.
04/18/23 12:24:18.257 (D_SECURITY:2) Can try token auth because we have at least one named credential.
04/18/23 12:24:18.257 (D_SECURITY:2) Will try IDTOKENS auth.
04/18/23 12:24:18.257 (D_SECURITY) Inserting pre-auth metadata for TOKEN.
04/18/23 12:24:18.257 (D_SECURITY) DC_AUTHENTICATE: our_policy:
AuthMethods = "FS,TOKEN,SCITOKENS,GSI,SSL"
Authentication = "REQUIRED"
CryptoMethods = "AES,BLOWFISH,3DES"
Enact = "NO"
Encryption = "OPTIONAL"
Integrity = "REQUIRED"
IssuerKeys = "POOL"
OutgoingNegotiation = "REQUIRED"
ParentUniqueID = "grid-htcondorce-dev02:24264:1681746325"
ServerPid = 24333
SessionDuration = "86400"
SessionLease = 3600
Subsystem = "SCHEDD"
TrustDomain = "grid-htcondorce-dev02.desy.de:9619"
04/18/23 12:24:18.257 (D_SECURITY) DC_AUTHENTICATE: the_policy:
AuthMethods = "SCITOKENS"
AuthMethodsList = "SCITOKENS"
Authentication = "YES"
CryptoMethods = "AES,BLOWFISH,3DES"
CryptoMethodsList = "AES,BLOWFISH,3DES"
Enact = "YES"
Encryption = "YES"
Integrity = "YES"
IssuerKeys = "POOL"
SessionDuration = "60"
SessionLease = 3600
TrustDomain = "grid-htcondorce-dev02.desy.de:9619"
04/18/23 12:24:18.257 (D_SECURITY) DC_AUTHENTICATE: generating AES-GCM key for session grid-htcondorce-dev02:24333:1681813458:2569...
04/18/23 12:24:18.257 (D_SECURITY) SECMAN: Sending following response ClassAd:
AuthMethods = "SCITOKENS"
AuthMethodsList = "SCITOKENS"
Authentication = "YES"
CryptoMethods = "AES"
CryptoMethodsList = "AES,BLOWFISH,3DES"
Enact = "YES"
Encryption = "YES"
Integrity = "YES"
IssuerKeys = "POOL"
RemoteVersion = "$CondorVersion: 9.0.15 Jul 20 2022 BuildID: 597761 PackageID: 9.0.15-1 $"
SessionDuration = "60"
SessionLease = 3600
TrustDomain = "grid-htcondorce-dev02.desy.de:9619"
04/18/23 12:24:18.257 (D_SECURITY) SECMAN: new session, doing initial authentication.
04/18/23 12:24:18.257 (D_SECURITY) Returning to DC while we wait for socket to authenticate.
04/18/23 12:24:18.257 (D_SECURITY) DC_AUTHENTICATE: received DC_AUTHENTICATE from <131.169.223.119:31685>
04/18/23 12:24:18.257 (D_SECURITY) DC_AUTHENTICATE: received following ClassAd:
AuthCommand = 60020
Command = 516
ConnectSinful = "<131.169.223.197:9619?addrs=131.169.223.197-9619+[2001-638-700-10df--1-c5]-9619&alias=grid-htcondorce-dev02.desy.de&noUDP&sock=schedd_24264_dce4>"
Sid = "grid-htcondorce-dev02:24333:1681813458:2568"
UseSession = "YES"
04/18/23 12:24:18.257 (D_SECURITY) DC_AUTHENTICATE: resuming session id grid-htcondorce-dev02:24333:1681813458:2568:
04/18/23 12:24:18.257 (D_SECURITY) DC_AUTHENTICATE: Cached Session:
AuthMethods = "FS"
AuthMethodsList = "FS,TOKEN,SCITOKENS,GSI,SSL"
Authentication = "NO"
CryptoMethodsList = "AES,BLOWFISH,3DES"
Enact = "YES"
Encryption = "NO"
Integrity = "NO"
IssuerKeys = "POOL"
RemoteVersion = "$CondorVersion: 9.0.15 Jul 20 2022 BuildID: 597761 PackageID: 9.0.15-1 $"
ServerPid = 2525633
SessionDuration = "60"
SessionLease = 3600
Sid = "grid-htcondorce-dev02:24333:1681813458:2568"
Subsystem = "TOOL"
TrustDomain = "grid-htcondorce-dev02.desy.de:9619"
User = "unauthenticated@unmapped"
ValidCommands = "60007,457,60020,443,441,6,12,5,515,516,1111,471"
04/18/23 12:24:18.257 (D_SECURITY) DC_AUTHENTICATE: not authenticating.
04/18/23 12:24:18.257 (D_SECURITY) DC_AUTHENTICATE: Success.
04/18/23 12:24:18.257 (D_ALWAYS) PERMISSION GRANTED to unauthenticated@unmapped from host 131.169.223.119 for command 516 (QUERY_JOB_ADS), access level READ: reason: READ authorization policy allows access by anyone
04/18/23 12:24:18.258 (D_COMMAND) Return from Handler <SharedPortEndpoint::HandleListenerAccept> 0.001134s
04/18/23 12:24:18.258 (D_COMMAND) Calling Handler <DaemonCore::HandleReqPayloadReady> (6)
04/18/23 12:24:18.258 (D_COMMAND) Calling HandleReq <command_query_job_ads> (0) for command 516 (QUERY_JOB_ADS) from unauthenticated@unmapped <131.169.223.119:31685>
04/18/23 12:24:18.258 (D_ALWAYS:2) ForkWorker::Fork: New child of 24333 = 228651
04/18/23 12:24:18.258 (D_ALWAYS) Number of Active Workers 0
04/18/23 12:24:18.258 (D_COMMAND) Return from HandleReq <command_query_job_ads> (handler: 0.000580s, sec: 0.000s, payload: 0.000s)
04/18/23 12:24:18.258 (D_COMMAND) Return from Handler <DaemonCore::HandleReqPayloadReady> 0.000620s
04/18/23 12:24:18.260 (D_COMMAND) DaemonCore: pid 228651 exited with status 0, invoking reaper 1 <ForkWork Reaper>
04/18/23 12:24:18.260 (D_COMMAND) DaemonCore: return from reaper for pid 228651
04/18/23 12:24:18.261 (D_COMMAND) Calling Handler <DaemonCommandProtocol::WaitForSocketData> (5)
04/18/23 12:24:18.261 (D_SECURITY) DC_AUTHENTICATE: authenticating RIGHT NOW.
04/18/23 12:24:18.261 (D_SECURITY) AUTHENTICATE: setting timeout for (unknown) to 20.
04/18/23 12:24:18.261 (D_SECURITY) AUTHENTICATE: in authenticate( addr == '(unknown)', methods == 'SCITOKENS')
04/18/23 12:24:18.261 (D_SECURITY) AUTHENTICATE: can still try these methods: SCITOKENS
04/18/23 12:24:18.261 (D_SECURITY) HANDSHAKE: in handshake(my_methods = 'SCITOKENS')
04/18/23 12:24:18.261 (D_SECURITY) HANDSHAKE: handshake() - i am the server
04/18/23 12:24:18.261 (D_SECURITY) HANDSHAKE: client sent (methods == 4096)
04/18/23 12:24:18.262 (D_SECURITY) HANDSHAKE: i picked (method == 4096)
04/18/23 12:24:18.262 (D_SECURITY) HANDSHAKE: client received (method == 4096)
04/18/23 12:24:18.262 (D_SECURITY) AUTHENTICATE: will try to use 4096 (SCITOKENS)
04/18/23 12:24:18.262 (D_SECURITY) AUTHENTICATE: do_authenticate is 1.
04/18/23 12:24:18.262 (D_SECURITY) CADIR: '/etc/grid-security/certificates'
04/18/23 12:24:18.262 (D_SECURITY) CERTFILE: '/etc/grid-security/hostcert.pem'
04/18/23 12:24:18.262 (D_SECURITY) KEYFILE: '/etc/grid-security/hostkey.pem'
04/18/23 12:24:18.262 (D_SECURITY) CIPHERLIST: 'ECDHE-ECDSA-CHACHA20-POLY1305:ECDHE-RSA-CHACHA20-POLY1305:ECDHE-ECDSA-AES128-GCM-SHA256:ECDHE-RSA-AES128-GCM-SHA256:ECDHE-ECDSA-AES256-GCM-SHA384:ECDHE-RSA-AES256-GCM-SHA384:DHE-RSA-AES128-GCM-SHA256:DHE-RSA-AES256-GCM-SHA384:ECDHE-ECDSA-AES128-SHA256:ECDHE-RSA-AES128-SHA256:ECDHE-ECDSA-AES128-SHA:ECDHE-RSA-AES256-SHA384:ECDHE-RSA-AES128-SHA:ECDHE-ECDSA-AES256-SHA384:ECDHE-ECDSA-AES256-SHA:ECDHE-RSA-AES256-SHA:DHE-RSA-AES128-SHA256:DHE-RSA-AES128-SHA:DHE-RSA-AES256-SHA256:DHE-RSA-AES256-SHA:ECDHE-ECDSA-DES-CBC3-SHA:ECDHE-RSA-DES-CBC3-SHA:EDH-RSA-DES-CBC3-SHA:AES128-GCM-SHA256:AES256-GCM-SHA384:AES128-SHA256:AES256-SHA256:AES128-SHA:AES256-SHA:DES-CBC3-SHA:!DSS'
04/18/23 12:24:18.262 (D_SECURITY) Will return to DC because authentication is incomplete.
04/18/23 12:24:18.262 (D_COMMAND) Return from Handler <DaemonCommandProtocol::WaitForSocketData> 0.000841s
04/18/23 12:24:18.270 (D_COMMAND) Calling Handler <DaemonCommandProtocol::WaitForSocketData> (5)
04/18/23 12:24:18.270 (D_SECURITY) SSL Auth: Trying to accept.
04/18/23 12:24:18.270 (D_SECURITY) Accept returned -1.
04/18/23 12:24:18.270 (D_SECURITY) SSL Auth: SSL: trying to continue reading.
04/18/23 12:24:18.270 (D_SECURITY) Round 0.
04/18/23 12:24:18.270 (D_SECURITY) SSL Auth: Receive message.
04/18/23 12:24:18.270 (D_SECURITY) Received message (2).
04/18/23 12:24:18.270 (D_SECURITY) Status (c: 2, s: 2)
04/18/23 12:24:18.270 (D_SECURITY) SSL Auth: Trying to accept.
04/18/23 12:24:18.270 (D_SECURITY) Accept returned -1.
04/18/23 12:24:18.270 (D_SECURITY) SSL Auth: SSL: trying to continue reading.
04/18/23 12:24:18.270 (D_SECURITY) Round 1.
04/18/23 12:24:18.270 (D_SECURITY) Send message (2).
04/18/23 12:24:18.270 (D_SECURITY) Status (c: 2, s: 2)
04/18/23 12:24:18.270 (D_SECURITY) SSL Auth: Trying to accept.
04/18/23 12:24:18.270 (D_SECURITY) Accept returned -1.
04/18/23 12:24:18.270 (D_SECURITY) SSL Auth: SSL: trying to continue reading.
04/18/23 12:24:18.270 (D_SECURITY) Round 2.
04/18/23 12:24:18.270 (D_SECURITY) SSL Auth: Would block when trying to receive message
04/18/23 12:24:18.270 (D_SECURITY) AUTHENTICATE: auth would still block
04/18/23 12:24:18.270 (D_SECURITY) Will return to DC to continue authentication..
04/18/23 12:24:18.270 (D_COMMAND) Return from Handler <DaemonCommandProtocol::WaitForSocketData> 0.000331s
04/18/23 12:24:18.272 (D_COMMAND) Calling Handler <DaemonCommandProtocol::WaitForSocketData> (5)
04/18/23 12:24:18.272 (D_SECURITY) SSL Auth: Trying to accept.
04/18/23 12:24:18.272 (D_SECURITY) Accept returned -1.
04/18/23 12:24:18.272 (D_SECURITY) SSL Auth: SSL: trying to continue reading.
04/18/23 12:24:18.272 (D_SECURITY) Round 2.
04/18/23 12:24:18.272 (D_SECURITY) SSL Auth: Receive message.
04/18/23 12:24:18.272 (D_SECURITY) Received message (2).
04/18/23 12:24:18.272 (D_SECURITY) Status (c: 2, s: 2)
04/18/23 12:24:18.272 (D_SECURITY) SSL Auth: Trying to accept.
04/18/23 12:24:18.279 (D_SECURITY) Accept returned 1.
04/18/23 12:24:18.279 (D_SECURITY) Round 3.
04/18/23 12:24:18.279 (D_SECURITY) Send message (4).
04/18/23 12:24:18.279 (D_SECURITY) Status (c: 2, s: 4)
04/18/23 12:24:18.279 (D_SECURITY) Round 4.
04/18/23 12:24:18.279 (D_SECURITY) SSL Auth: Would block when trying to receive message
04/18/23 12:24:18.279 (D_SECURITY) AUTHENTICATE: auth would still block
04/18/23 12:24:18.279 (D_SECURITY) Will return to DC to continue authentication..
04/18/23 12:24:18.279 (D_COMMAND) Return from Handler <DaemonCommandProtocol::WaitForSocketData> 0.006583s
04/18/23 12:24:18.281 (D_COMMAND) Calling Handler <DaemonCommandProtocol::WaitForSocketData> (5)
04/18/23 12:24:18.281 (D_SECURITY) Round 4.
04/18/23 12:24:18.281 (D_SECURITY) SSL Auth: Receive message.
04/18/23 12:24:18.281 (D_SECURITY) Received message (4).
04/18/23 12:24:18.281 (D_SECURITY) Status (c: 4, s: 4)
04/18/23 12:24:18.281 (D_SECURITY) SSL Auth: Server trying post connection check.
04/18/23 12:24:18.281 (D_SECURITY) SSL Auth: post_connection_check.
04/18/23 12:24:18.281 (D_SECURITY) SSL Auth: Anonymous client is allowed; not checking.
04/18/23 12:24:18.281 (D_SECURITY) Writing round 0.
04/18/23 12:24:18.281 (D_SECURITY) SSL write has succeeded.
04/18/23 12:24:18.281 (D_SECURITY) Send message (4).
04/18/23 12:24:18.281 (D_SECURITY) Status: c: 2, s: 4
04/18/23 12:24:18.281 (D_SECURITY) Writing round 1.
04/18/23 12:24:18.281 (D_SECURITY) SSL write has succeeded.
04/18/23 12:24:18.281 (D_SECURITY) SSL Auth: Would block when trying to receive message
04/18/23 12:24:18.281 (D_SECURITY) AUTHENTICATE: auth would still block
04/18/23 12:24:18.281 (D_SECURITY) Will return to DC to continue authentication..
04/18/23 12:24:18.281 (D_COMMAND) Return from Handler <DaemonCommandProtocol::WaitForSocketData> 0.000142s
04/18/23 12:24:18.282 (D_COMMAND) Calling Handler <DaemonCommandProtocol::WaitForSocketData> (5)
04/18/23 12:24:18.282 (D_SECURITY) Writing round 1.
04/18/23 12:24:18.282 (D_SECURITY) SSL write has succeeded.
04/18/23 12:24:18.282 (D_SECURITY) SSL Auth: Receive message.
04/18/23 12:24:18.282 (D_SECURITY) Received message (4).
04/18/23 12:24:18.282 (D_SECURITY) Status: c: 4, s: 4
04/18/23 12:24:18.282 (D_SECURITY:2) CRYPTO: simple reset m_ivec(len 8) and m_num
04/18/23 12:24:18.282 (D_SECURITY) Reading SciTokens round 0.
04/18/23 12:24:18.282 (D_SECURITY) SSL Auth: SciToken: continue read/write.
04/18/23 12:24:18.282 (D_SECURITY) SSL Auth: Receive message.
04/18/23 12:24:18.282 (D_SECURITY) Received message (4).
04/18/23 12:24:18.282 (D_SECURITY) SciToken exchange server status: c: 4, s: 2
04/18/23 12:24:18.282 (D_SECURITY) Reading SciTokens round 1.
04/18/23 12:24:18.282 (D_SECURITY:2) Peeked at the sent token; 730 bytes long; SSL status 4.
04/18/23 12:24:18.282 (D_SECURITY) SciToken SSL read is successful.
04/18/23 12:24:22.680 (D_SECURITY) SCITOKENS:2:Failed to verify token and generate ACLs: Timeout was reached
04/18/23 12:24:22.681 (D_SECURITY:2) AUTHENTICATION: map file already loaded.
04/18/23 12:24:22.681 (D_ERROR) Failed to map SCITOKENS authenticated identity '', failing authentication to give another authentication method a go.
04/18/23 12:24:22.681 (D_SECURITY) Send message (3).
04/18/23 12:24:22.681 (D_SECURITY) SciToken exchange server status: c: 4, s: 3
04/18/23 12:24:22.681 (D_SECURITY) SSL Auth: SciToken Authentication failed at token exchange.
04/18/23 12:24:22.681 (D_SECURITY) AUTHENTICATE: do_authenticate is 0.
04/18/23 12:24:22.681 (D_SECURITY) AUTHENTICATE: method 4096 (SCITOKENS) failed.
04/18/23 12:24:22.681 (D_SECURITY) AUTHENTICATE: can still try these methods: SCITOKENS
04/18/23 12:24:22.681 (D_SECURITY) HANDSHAKE: in handshake(my_methods = 'SCITOKENS')
04/18/23 12:24:22.681 (D_SECURITY) AUTHENTICATE: handshake would block
04/18/23 12:24:22.681 (D_SECURITY) Will return to DC to continue authentication..
04/18/23 12:24:22.681 (D_COMMAND) Return from Handler <DaemonCommandProtocol::WaitForSocketData> 4.398876s
04/18/23 12:24:22.682 (D_COMMAND) Calling Handler <DaemonCommandProtocol::WaitForSocketData> (5)
04/18/23 12:24:22.682 (D_SECURITY) HANDSHAKE: handshake() - i am the server
04/18/23 12:24:22.683 (D_SECURITY) HANDSHAKE: client sent (methods == 0)
04/18/23 12:24:22.683 (D_SECURITY) HANDSHAKE: i picked (method == 0)
04/18/23 12:24:22.683 (D_SECURITY) HANDSHAKE: client received (method == 0)
04/18/23 12:24:22.683 (D_SECURITY) AUTHENTICATE: can still try these methods: SCITOKENS
04/18/23 12:24:22.683 (D_SECURITY:2) AUTHENTICATE: no available authentication methods succeeded!
04/18/23 12:24:22.683 (D_ALWAYS) DC_AUTHENTICATE: required authentication of 131.169.223.90 failed: AUTHENTICATE:1003:Failed to authenticate with any method|AUTHENTICATE:1004:Failed to authenticate using SCITOKENS
04/18/23 12:24:22.683 (D_COMMAND) Return from Handler <DaemonCommandProtocol::WaitForSocketData> 0.000350s
04/18/23 12:24:27.688 (D_ALWAYS:2) ShouldStartJob: job=0.01 cur=0.00 max=0.10
04/18/23 12:24:27.688 (D_ALWAYS:2) CronJob: Starting job 'CEVIEW' (/usr/share/condor-ce/condor_ce_jobmetrics)
04/18/23 12:24:27.688 (D_ALWAYS:2) Create_Process: using fast clone() to create child process.
04/18/23 12:24:27.823 (D_COMMAND) Calling Handler <SharedPortEndpoint::HandleListenerAccept> (0)
04/18/23 12:24:27.823 (D_SECURITY) DC_AUTHENTICATE: received DC_AUTHENTICATE from <131.169.223.197:1772>
04/18/23 12:24:27.823 (D_SECURITY) DC_AUTHENTICATE: received following ClassAd:
AuthMethods = "FS,TOKEN,SCITOKENS,GSI,SSL"
Authentication = "OPTIONAL"
Command = 516
ConnectSinful = "<131.169.223.197:9619?addrs=131.169.223.197-9619+[2001-638-700-10df--1-c5]-9619&alias=grid-htcondorce-dev02.desy.de&noUDP&sock=schedd_24264_dce4>"
CryptoMethods = "AES,BLOWFISH,3DES"
Enact = "NO"
Encryption = "OPTIONAL"
Integrity = "OPTIONAL"
NewSession = "YES"
OutgoingNegotiation = "PREFERRED"
ParentUniqueID = "grid-htcondorce-dev02:24333:1681746326"
RemoteVersion = "$CondorVersion: 9.0.15 Jul 20 2022 BuildID: 597761 PackageID: 9.0.15-1 $"
ServerPid = 228668
SessionDuration = "60"
SessionLease = 3600
Subsystem = "TOOL"
TrustDomain = "grid-htcondorce-dev02.desy.de:9619"
04/18/23 12:24:27.823 (D_SECURITY:2) Filtering authentication methods (FS,TOKEN,SCITOKENS,GSI,SSL) prior to offering them remotely.
04/18/23 12:24:27.823 (D_SECURITY:2) Can try token auth because we have at least one named credential.
04/18/23 12:24:27.823 (D_SECURITY:2) Will try IDTOKENS auth.
04/18/23 12:24:27.823 (D_SECURITY) Inserting pre-auth metadata for TOKEN.
04/18/23 12:24:27.823 (D_SECURITY) DC_AUTHENTICATE: our_policy:
AuthMethods = "FS,TOKEN,SCITOKENS,GSI,SSL"
Authentication = "OPTIONAL"
CryptoMethods = "AES,BLOWFISH,3DES"
Enact = "NO"
Encryption = "OPTIONAL"
Integrity = "OPTIONAL"
IssuerKeys = "POOL"
OutgoingNegotiation = "PREFERRED"
ParentUniqueID = "grid-htcondorce-dev02:24264:1681746325"
ServerPid = 24333
SessionDuration = "86400"
SessionLease = 3600
Subsystem = "SCHEDD"
TrustDomain = "grid-htcondorce-dev02.desy.de:9619"
04/18/23 12:24:27.824 (D_SECURITY) DC_AUTHENTICATE: the_policy:
AuthMethods = "FS"
AuthMethodsList = "FS,TOKEN,SCITOKENS,GSI,SSL"
Authentication = "NO"
CryptoMethods = "AES,BLOWFISH,3DES"
CryptoMethodsList = "AES,BLOWFISH,3DES"
Enact = "YES"
Encryption = "NO"
Integrity = "NO"
IssuerKeys = "POOL"
SessionDuration = "60"
SessionLease = 3600
TrustDomain = "grid-htcondorce-dev02.desy.de:9619"
04/18/23 12:24:27.824 (D_SECURITY) SECMAN: Sending following response ClassAd:
AuthMethods = "FS"
AuthMethodsList = "FS,TOKEN,SCITOKENS,GSI,SSL"
Authentication = "NO"
CryptoMethodsList = "AES,BLOWFISH,3DES"
Enact = "YES"
Encryption = "NO"
Integrity = "NO"
IssuerKeys = "POOL"
RemoteVersion = "$CondorVersion: 9.0.15 Jul 20 2022 BuildID: 597761 PackageID: 9.0.15-1 $"
SessionDuration = "60"
SessionLease = 3600
TrustDomain = "grid-htcondorce-dev02.desy.de:9619"
04/18/23 12:24:27.824 (D_SECURITY) DC_AUTHENTICATE: not authenticating.
04/18/23 12:24:27.824 (D_SECURITY) DC_AUTHENTICATE: Success.
04/18/23 12:24:27.824 (D_ALWAYS) PERMISSION GRANTED to unauthenticated@unmapped from host 131.169.223.197 for command 516 (QUERY_JOB_ADS), access level READ: reason: READ authorization policy allows access by anyone
04/18/23 12:24:27.824 (D_SECURITY) DC_AUTHENTICATE: sending session ad:
ReturnCode = "AUTHORIZED"
Sid = "grid-htcondorce-dev02:24333:1681813467:2570"
User = "unauthenticated@unmapped"
ValidCommands = "60007,457,60020,443,441,6,12,5,515,516,1111,471"
04/18/23 12:24:27.824 (D_SECURITY) DC_AUTHENTICATE: sent session grid-htcondorce-dev02:24333:1681813467:2570 info!
04/18/23 12:24:27.824 (D_SECURITY:2) SESSION: fallback crypto method would be BLOWFISH.
04/18/23 12:24:27.824 (D_SECURITY:2) SESSION: server checking key type: -1
04/18/23 12:24:27.824 (D_SECURITY) DC_AUTHENTICATE: added incoming session id grid-htcondorce-dev02:24333:1681813467:2570 to cache for 80 seconds (lease is 3620s, return address is unknown).
AuthMethods = "FS"
AuthMethodsList = "FS,TOKEN,SCITOKENS,GSI,SSL"
Authentication = "NO"
CryptoMethodsList = "AES,BLOWFISH,3DES"
Enact = "YES"
Encryption = "NO"
Integrity = "NO"
IssuerKeys = "POOL"
ParentUniqueID = "grid-htcondorce-dev02:24333:1681746326"
RemoteVersion = "$CondorVersion: 9.0.15 Jul 20 2022 BuildID: 597761 PackageID: 9.0.15-1 $"
ServerPid = 228668
SessionDuration = "60"
SessionLease = 3600
Sid = "grid-htcondorce-dev02:24333:1681813467:2570"
Subsystem = "TOOL"
TrustDomain = "grid-htcondorce-dev02.desy.de:9619"
User = "unauthenticated@unmapped"
ValidCommands = "60007,457,60020,443,441,6,12,5,515,516,1111,471"
04/18/23 12:24:27.824 (D_COMMAND) Return from Handler <SharedPortEndpoint::HandleListenerAccept> 0.000742s
04/18/23 12:24:27.824 (D_COMMAND) Calling Handler <DaemonCore::HandleReqPayloadReady> (5)
04/18/23 12:24:27.824 (D_COMMAND) Calling HandleReq <command_query_job_ads> (0) for command 516 (QUERY_JOB_ADS) from unauthenticated@unmapped <131.169.223.197:1772>
04/18/23 12:24:27.825 (D_ALWAYS:2) ForkWorker::Fork: New child of 24333 = 228680
04/18/23 12:24:27.825 (D_ALWAYS) Number of Active Workers 0
04/18/23 12:24:27.825 (D_COMMAND) Return from HandleReq <command_query_job_ads> (handler: 0.000549s, sec: 0.001s, payload: 0.000s)
04/18/23 12:24:27.825 (D_COMMAND) Return from Handler <DaemonCore::HandleReqPayloadReady> 0.000581s
04/18/23 12:24:27.826 (D_COMMAND) DaemonCore: pid 228680 exited with status 0, invoking reaper 1 <ForkWork Reaper>
04/18/23 12:24:27.826 (D_COMMAND) DaemonCore: return from reaper for pid 228680
04/18/23 12:24:27.840 (D_COMMAND) Calling pipe Handler <Standard Out Handler> for Pipe end=65536 <Standard Out>
04/18/23 12:24:27.840 (D_ALWAYS:2) CEVIEW: 4 lines in Queue
04/18/23 12:24:27.840 (D_ALWAYS:2) Replacing ClassAd for 'CEVIEW'
04/18/23 12:24:27.840 (D_COMMAND) Return from pipe Handler
04/18/23 12:24:27.922 (D_COMMAND) Calling pipe Handler <Standard Error Handler> for Pipe end=65538 <Standard Error>
04/18/23 12:24:27.922 (D_ALWAYS:2) CEVIEW: Processing CE grid-htcondorce-dev02.desy.de.
04/18/23 12:24:27.922 (D_COMMAND) Return from pipe Handler
04/18/23 12:24:27.935 (D_COMMAND) Calling pipe Handler <Standard Out Handler> for Pipe end=65536 <Standard Out>
04/18/23 12:24:27.935 (D_ALWAYS:2) CronJob: STDOUT closed for 'CEVIEW'
04/18/23 12:24:27.935 (D_COMMAND) Return from pipe Handler
04/18/23 12:24:27.935 (D_COMMAND) Calling pipe Handler <Standard Error Handler> for Pipe end=65538 <Standard Error>
04/18/23 12:24:27.935 (D_ALWAYS:2) CronJob: STDERR closed for 'CEVIEW'
04/18/23 12:24:27.935 (D_COMMAND) Return from pipe Handler
04/18/23 12:24:27.935 (D_COMMAND) DaemonCore: pid 228664 exited with status 0, invoking reaper 2 <Cron Reaper>
04/18/23 12:24:27.935 (D_ALWAYS:2) CronJob: 'CEVIEW' (pid 228664) exit_status=0
04/18/23 12:24:27.935 (D_COMMAND) DaemonCore: return from reaper for pid 228664
04/18/23 12:24:27.935 (D_ALWAYS:2) CronJob::Schedule 'CEVIEW' IR=F IP=T IWE=F IOS=F IOD=F nr=374 nf=0
Attachment:
smime.p7s
Description: S/MIME Cryptographic Signature