Rpc error code deadlineexceeded desc context deadline exceeded golang

Hi, I have written a simple gRPC server and client applications which will encrypt and decrypt a text. I tried running the client continuously one by one. It works great. No issue up to this point....

Hi,

I have written a simple gRPC server and client applications which will encrypt and decrypt a text. I tried running the client continuously one by one. It works great. No issue up to this point.

I tried running those server and client applications as docker containers. I ran this server as a container in a machine and then tried running the client containers one by one continuously by running a simple bash script.

#!/bin/bash
# Basic while loop
counter=1
while [ $counter -le 10 ]
do
        echo client-$counter
        docker run  client:latest
((counter++))
done

it could run only 3 to 4 instances of client. After it resulting in the below error.
rpc error: code = DeadlineExceeded desc = context deadline

Find the below client and server code :

server sample code :

func main(){
lis, err := net.Listen("tcp", port)
	if err != nil {
		log.Fatalf("failed to listen: %v", err)
	}
	s := grpc.NewServer()
	pb.RegisterGolangServer(s, &server{})
	log.Printf("server/main:main() server listening at %v", lis.Addr())
	if err := s.Serve(lis); err != nil {
		log.Fatalf("server/main:main() failed to serve: %v", err)
	}
	return
}

Sample client code :

func init(){
conn, err := grpc.Dial(addr, grpc.WithInsecure(), grpc.WithBlock())
if err != nil {
log.Fatalf("did not connect: %v", err)
}
defer conn.Close()
log.Println("Establishing connection from Init in session package")
_, err = EstablishSession(conn)
}

func EstablishSession(conn *grpc.ClientConn) (*SessionDetailsStore, error) {

c := pb.NewGolangClient(conn)
nonce := make([]byte, nonceLength)
if _, err := io.ReadFull(rand.Reader, nonce); err != nil {
log.Printf("sessionlib/session:EstablishSession() Error in nonce creation: ", err)
return nil, errors.New("error in nonce creation")
}

skcserver_token := []byte(aas_token)

ctx, cancel := context.WithTimeout(context.Background(), time.Second)
defer cancel()
r, err := c.Session(ctx, &pb.SessionRequest{SkcserverToken: skcserver_token, Nonce: nonce})
if err != nil {
log.Printf("sessionlib/session:EstablishSession() Could not create session: %v", err)
return nil, errors.New("could not create session")
}
return nil, nil
}

In client side, I use this establishsession() function to get the session ID and using it for the encryption and decryption process of my text.

(Point to note : Both encryption and decryption processes have to reach the server for 4 times each during the client runtime.)

Find the below server and client logs :

Client :

client-4

2022/01/05 14:57:45 Establishing connection from Init in session package
2022/01/05 14:57:45 sessionlib/session:EstablishSession() Entering
2022/01/05 14:57:45 sessionlib/session:EstablishSession() Success in establishing session
2022/01/05 14:57:45 sessionlib/session:EstablishSession() Session ID : [33 241 217 25 54 129 29 39 152 119 168 157 2 8 91 32]
2022/01/05 14:57:45 sessionlib/session:EstablishSession() Attestation Evidence : [116 101 115 116 113 117 111 116 101]
2022/01/05 14:57:45 sessionlib/session:EstablishSession() Leaving
2022/01/05 14:57:45 client/main:main() Entering
2022/01/05 14:57:45 client/main:main() Calling skc-crypto-application which in turn call crypto functions
2022/01/05 14:57:45 crypto_app/crypto_app:cryptoFunctions() Entering
time="2022-01-05T14:57:45Z" level=info msg="config/config:validateConfiguration() Entering"
time="2022-01-05T14:57:45Z" level=info msg="config/config:validateUserPermissions() Entering"
time="2022-01-05T14:57:45Z" level=info msg="config/config:validateUserPermissions() User global_admin_user has required permission(s)"
time="2022-01-05T14:57:45Z" level=info msg="config/config:validateUserPermissions() Leaving"
time="2022-01-05T14:57:45Z" level=info msg="config/config:validateConfiguration() Leaving"
2022/01/05 14:57:45 crypto/aes/cipher:NewCipher() Entering
2022/01/05 14:57:45 crypto/aes/cipher:NewCipher() get session ID for NewCipher
2022/01/05 14:57:45 crypto/aes/cipher:GetSessionId() Entering
crypto_app/crypto_app:cryptoFunctions() we are going to encrypt:
 Mandalorian is currently the best DisneyPlus show
2022/01/05 14:57:45 crypto/aes/cipher:GetSessionId() try getting session details -  aes
2022/01/05 14:57:45 sessionlib/session:EstablishSession() Entering
2022/01/05 14:57:45 sessionlib/session:EstablishSession() Session has been established already. So returning the details
2022/01/05 14:57:45 sessionlib/session:EstablishSession() Leaving
2022/01/05 14:57:45 crypto/aes/cipher:GetSessionId() Leaving
time="2022-01-05T14:57:45Z" level=info msg="config/config:validateConfiguration() Entering"
time="2022-01-05T14:57:45Z" level=info msg="config/config:validateUserPermissions() Entering"
time="2022-01-05T14:57:45Z" level=info msg="config/config:validateUserPermissions() User global_admin_user has required permission(s)"
time="2022-01-05T14:57:45Z" level=info msg="config/config:validateUserPermissions() Leaving"
time="2022-01-05T14:57:45Z" level=info msg="config/config:validateConfiguration() Leaving"
2022/01/05 14:57:45 crypto/aes/cipher:NewCipher() get new cipher from NewCipher skc server
crypto_app/crypto_app:cryptoFunctions() cipher id in crypto app =  [66 56 51 52 67 51 66 48]
2022/01/05 14:57:45 crypto/aes/cipher:NewCipher() NewCipher Attestation ID  attestation_id:"xefx0bx0c=xe1xb2lxd2tx8axc1xe8-x0cx9ax83x19x05x81xf3xe8xe5x89Oxbfxc54_ݗxdaxfd0Axa9Qx03u1ãx84Xxe5xe3x8cx04exa6Aܨx9dfxabxf9z,x1bx1cxa6`xx8a"
2022/01/05 14:57:45 crypto/aes/cipher:NewCipher() Leaving
2022/01/05 14:57:45 crypto/cipher/gcm:NewGCM() Entering
2022/01/05 14:57:45 crypto/cipher/gcm:GetSessionId() Entering
2022/01/05 14:57:45 crypto/cipher/gcm:GetSessionId() try getting session details - cipher
2022/01/05 14:57:45 sessionlib/session:EstablishSession() Entering
2022/01/05 14:57:45 sessionlib/session:EstablishSession() Session has been established already. So returning the details
2022/01/05 14:57:45 sessionlib/session:EstablishSession() Leaving
2022/01/05 14:57:45 crypto/cipher/gcm:GetSessionId() Leaving
2022/01/05 14:57:45 crypto/cipher/gcm:NewGCM() session id : [33 241 217 25 54 129 29 39 152 119 168 157 2 8 91 32]
2022/01/05 14:57:45 crypto/cipher/gcm:GetSessionId() Entering
2022/01/05 14:57:45 crypto/cipher/gcm:GetSessionId() try getting session details - cipher
2022/01/05 14:57:45 sessionlib/session:EstablishSession() Entering
2022/01/05 14:57:45 sessionlib/session:EstablishSession() Session has been established already. So returning the details
2022/01/05 14:57:45 sessionlib/session:EstablishSession() Leaving
2022/01/05 14:57:45 crypto/cipher/gcm:GetSessionId() Leaving
2022/01/05 14:57:45 crypto/cipher/gcm:NewGCM() get new cipher from NewGCM skc server
2022/01/05 14:57:45 crypto/cipher/gcm:NewGCM() Get session ID for NewCipher cphr value ->  QjgzNEMzQjA=
crypto_app/crypto_app:cryptoFunctions() gcm_id =  [66 56 53 49 50 52 51 48]
2022/01/05 14:57:45 crypto/cipher/gcm:NewGCM() New gcm id in gcm.go =  [66 56 53 49 50 52 51 48]
2022/01/05 14:57:45 crypto/cipher/gcm:NewGCM() Leaving
2022/01/05 14:57:45 crypto/cipher/gcm:NonceSize() Entering
2022/01/05 14:57:45 crypto/cipher/gcm:GetSessionId() Entering
2022/01/05 14:57:45 crypto/cipher/gcm:GetSessionId() try getting session details - cipher
2022/01/05 14:57:45 sessionlib/session:EstablishSession() Entering
2022/01/05 14:57:45 sessionlib/session:EstablishSession() Session has been established already. So returning the details
2022/01/05 14:57:45 sessionlib/session:EstablishSession() Leaving
2022/01/05 14:57:45 crypto/cipher/gcm:GetSessionId() Leaving
2022/01/05 14:57:45 crypto/cipher/gcm:NonceSize() session id: [33 241 217 25 54 129 29 39 152 119 168 157 2 8 91 32]
2022/01/05 14:57:45 crypto/cipher/gcm:GetSessionId() Entering
2022/01/05 14:57:45 crypto/cipher/gcm:GetSessionId() try getting session details - cipher
2022/01/05 14:57:45 sessionlib/session:EstablishSession() Entering
2022/01/05 14:57:45 sessionlib/session:EstablishSession() Session has been established already. So returning the details
2022/01/05 14:57:45 sessionlib/session:EstablishSession() Leaving
2022/01/05 14:57:45 crypto/cipher/gcm:GetSessionId() Leaving
2022/01/05 14:57:45 crypto/cipher/gcm:NonceSize() get nonce from the server
crypto_app/crypto_app:cryptoFunctions() nonceSize =  12
2022/01/05 14:57:45 crypto/cipher/gcm:NonceSize() Leaving
2022/01/05 14:57:45 crypto/cipher/gcm:Seal() Entering
2022/01/05 14:57:45 crypto/cipher/gcm:GetSessionId() Entering
2022/01/05 14:57:45 crypto/cipher/gcm:GetSessionId() try getting session details - cipher
2022/01/05 14:57:45 sessionlib/session:EstablishSession() Entering
2022/01/05 14:57:45 sessionlib/session:EstablishSession() Session has been established already. So returning the details
2022/01/05 14:57:45 sessionlib/session:EstablishSession() Leaving
2022/01/05 14:57:45 crypto/cipher/gcm:GetSessionId() Leaving
2022/01/05 14:57:45 crypto/cipher/gcm:Seal() session id: [33 241 217 25 54 129 29 39 152 119 168 157 2 8 91 32]
2022/01/05 14:57:45 crypto/cipher/gcm:GetSessionId() Entering
2022/01/05 14:57:45 crypto/cipher/gcm:GetSessionId() try getting session details - cipher
2022/01/05 14:57:45 sessionlib/session:EstablishSession() Entering
2022/01/05 14:57:45 sessionlib/session:EstablishSession() Session has been established already. So returning the details
2022/01/05 14:57:45 sessionlib/session:EstablishSession() Leaving
2022/01/05 14:57:45 crypto/cipher/gcm:GetSessionId() Leaving
2022/01/05 14:57:46 crypto/cipher/gcm:Seal() get the cipher text from server
2022/01/05 14:57:46 crypto/cipher/gcm:Seal() Leaving
2022/01/05 14:57:46 crypto/aes/cipher:NewCipher() Entering
2022/01/05 14:57:46 crypto/aes/cipher:NewCipher() get session ID for NewCipher
2022/01/05 14:57:46 crypto/aes/cipher:GetSessionId() Entering
crypto_app/crypto_app:cryptoFunctions() cipherText =  [175 74 224 81 86 167 69 186 18 125 213 235 155 199 211 134 173 31 217 183 58 81 182 108 123 24 125 40 166 216 43 3 3 118 9 16 95 39 250 33 194 131 230 6 169 131 49 228 74 223 161 220 67 35 151 110 65 14 46 123 184 179 4 159 86 191 188 151 180 38 251 198 175 101 184 89 182]
2022/01/05 14:59:46 crypto/aes/cipher:GetSessionId() try getting session details -  aes
2022/01/05 14:59:46 sessionlib/session:EstablishSession() Entering
2022/01/05 14:59:46 sessionlib/session:EstablishSession() Session has been established already. So returning the details
2022/01/05 14:59:46 sessionlib/session:EstablishSession() Leaving
2022/01/05 14:59:46 crypto/aes/cipher:GetSessionId() Leaving

time="2022-01-05T15:05:46Z" level=info msg="config/config:validateConfiguration() Entering"
time="2022-01-05T15:05:46Z" level=info msg="config/config:validateUserPermissions() Entering"
time="2022-01-05T15:05:46Z" level=info msg="config/config:validateUserPermissions() User global_admin_user has required permission(s)"
time="2022-01-05T15:05:46Z" level=info msg="config/config:validateUserPermissions() Leaving"
time="2022-01-05T15:05:46Z" level=info msg="config/config:validateConfiguration() Leaving"
2022/01/05 15:05:46 crypto/aes/cipher:NewCipher() get new cipher from NewCipher skc server
2022/01/05 15:05:56 crypto/aes/cipher:NewCipher() NewCipher failed with: rpc error: code = DeadlineExceeded desc = context deadline exceeded
2022/01/05 15:05:56 crypto/aes/cipher:NewCipher() Leaving
2022/01/05 15:05:56 crypto/cipher/gcm:NewGCM() Entering
2022/01/05 15:05:56 crypto/cipher/gcm:GetSessionId() Entering
crypto_app/crypto_app:cryptoFunctions() Failed to create cphr_id using aes.NewCipher rpc error: code = DeadlineExceeded desc = context deadline exceededcrypto_app/crypto_app:cryptoFunctions() cipher id in decryption process =  []

2022/01/05 15:14:46 crypto/cipher/gcm:GetSessionId() try getting session details - cipher
2022/01/05 15:14:46 sessionlib/session:EstablishSession() Entering
2022/01/05 15:14:46 sessionlib/session:EstablishSession() Session has been established already. So returning the details
2022/01/05 15:14:46 sessionlib/session:EstablishSession() Leaving
2022/01/05 15:14:46 crypto/cipher/gcm:GetSessionId() Leaving
2022/01/05 15:14:46 crypto/cipher/gcm:NewGCM() session id : [33 241 217 25 54 129 29 39 152 119 168 157 2 8 91 32]
2022/01/05 15:14:46 crypto/cipher/gcm:GetSessionId() Entering

2022/01/05 15:16:46 crypto/cipher/gcm:GetSessionId() try getting session details - cipher
2022/01/05 15:16:46 sessionlib/session:EstablishSession() Entering
2022/01/05 15:16:46 sessionlib/session:EstablishSession() Session has been established already. So returning the details
2022/01/05 15:16:46 sessionlib/session:EstablishSession() Leaving
2022/01/05 15:16:46 crypto/cipher/gcm:GetSessionId() Leaving

2022/01/05 15:18:46 crypto/cipher/gcm:NewGCM() get new cipher from NewGCM skc server
2022/01/05 15:18:46 crypto/cipher/gcm:NewGCM() Get session ID for NewCipher cphr value ->
2022/01/05 15:18:47 crypto/cipher/gcm:NewGCM() Unable to create NewGCM failed with error rpc error: code = DeadlineExceeded desc = context deadline exceeded
2022/01/05 15:18:47 crypto/cipher/gcm:NewGCM() Leaving
2022/01/05 15:18:47 crypto/cipher/gcm:NonceSize() Entering
2022/01/05 15:18:47 crypto/cipher/gcm:GetSessionId() Entering
crypto_app/crypto_app:cryptoFunctions() Failed to create gcm_id using NewGCM rpc error: code = DeadlineExceeded desc = context deadline exceededcrypto_app/crypto_app:cryptoFunctions() gcm_id in decryption process =  []

2022/01/05 15:20:46 crypto/cipher/gcm:GetSessionId() try getting session details - cipher
2022/01/05 15:20:46 sessionlib/session:EstablishSession() Entering
2022/01/05 15:20:46 sessionlib/session:EstablishSession() Session has been established already. So returning the details
2022/01/05 15:20:46 sessionlib/session:EstablishSession() Leaving
2022/01/05 15:20:46 crypto/cipher/gcm:GetSessionId() Leaving
2022/01/05 15:20:46 crypto/cipher/gcm:NonceSize() session id: [33 241 217 25 54 129 29 39 152 119 168 157 2 8 91 32]
2022/01/05 15:20:46 crypto/cipher/gcm:GetSessionId() Entering

2022/01/05 15:22:46 crypto/cipher/gcm:GetSessionId() try getting session details - cipher
2022/01/05 15:22:46 sessionlib/session:EstablishSession() Entering
2022/01/05 15:22:46 sessionlib/session:EstablishSession() Session has been established already. So returning the details
2022/01/05 15:22:46 sessionlib/session:EstablishSession() Leaving
2022/01/05 15:22:46 crypto/cipher/gcm:GetSessionId() Leaving

2022/01/05 15:24:47 crypto/cipher/gcm:NonceSize() get nonce from the server
2022/01/05 15:24:48 crypto/cipher/gcm:NonceSize() Failed to perform NonceSize request rpc error: code = DeadlineExceeded desc = context deadline exceeded
2022/01/05 15:24:48 crypto/cipher/gcm:NonceSize() Leaving
2022/01/05 15:24:48 crypto/cipher/gcm:Open() Entering
2022/01/05 15:24:48 crypto/cipher/gcm:GetSessionId() Entering
crypto_app/crypto_app:cryptoFunctions() Failed to create nonce using Nonce rpc error: code = DeadlineExceeded desc = context deadline exceededcrypto_app/crypto_app:cryptoFunctions() nonceSize in decryption process =  0

2022/01/05 15:33:47 crypto/cipher/gcm:GetSessionId() try getting session details - cipher
2022/01/05 15:33:47 sessionlib/session:EstablishSession() Entering
2022/01/05 15:33:47 sessionlib/session:EstablishSession() Session has been established already. So returning the details
2022/01/05 15:33:47 sessionlib/session:EstablishSession() Leaving
2022/01/05 15:33:47 crypto/cipher/gcm:GetSessionId() Leaving
2022/01/05 15:33:47 crypto/cipher/gcm:Open() session id: [33 241 217 25 54 129 29 39 152 119 168 157 2 8 91 32]
2022/01/05 15:33:47 crypto/cipher/gcm:GetSessionId() Entering

2022/01/05 15:35:47 crypto/cipher/gcm:GetSessionId() try getting session details - cipher
2022/01/05 15:35:47 sessionlib/session:EstablishSession() Entering
2022/01/05 15:35:47 sessionlib/session:EstablishSession() Session has been established already. So returning the details
2022/01/05 15:35:47 sessionlib/session:EstablishSession() Leaving
2022/01/05 15:35:47 crypto/cipher/gcm:GetSessionId() Leaving

2022/01/05 15:37:47 crypto/cipher/gcm:Open() get decrypted text from the server
2022/01/05 15:37:48 crypto/cipher/gcm:Open() Failed to perform Open request rpc error: code = DeadlineExceeded desc = context deadline exceeded
2022/01/05 15:37:48 crypto/cipher/gcm:Open() Leaving
2022/01/05 15:37:48 crypto_app/crypto_app:cryptoFunctions() Leaving
2022/01/05 15:37:48 client/main:main() Leaving
crypto_app/crypto_app:cryptoFunctions() Failed to get plainText using Open rpc error: code = DeadlineExceeded desc = context deadline exceededcrypto_app/crypto_app:cryptoFunctions() after decryption:

Server :

2022/01/05 14:57:27 server/main:main() Entering
2022/01/05 14:57:27 clients/kbs/kbs:Run() Entering
2022/01/05 14:57:27 clients/kbs/kbs:Run() Creating envelope key
2022/01/05 14:57:27 clients/kbs/kbs:Run() Leaving
[P1:T1:skcserver] error: bind: invalid handle returned
2022/01/05 14:57:27 server/main:main() server listening at [::]:50051
2022/01/05 14:57:27 server/main:validateAllSession() Entering
2022/01/05 14:57:27 server/main:validateAllSession() Leaving
2022/01/05 14:57:35 server/main:Session() Entering
2022/01/05 14:57:35 server/main:Session() Leaving
2022/01/05 14:57:35 server/main:NewCipher() Entering
2022/01/05 14:57:35 server/main:NewCipher() SessionID  D2byzSx5vTMXIQBJyhtsVQ==
2022/01/05 14:57:35 server/main:validateThisSession() Entering
2022/01/05 14:57:35 server/main:validateThisSession() Leaving
2022/01/05 14:57:35 server/main:NewCipher() Session id received:  [15 102 242 205 44 121 189 51 23 33 0 73 202 27 108 85]
2022/01/05 14:57:35 server/main:NewCipher() Received key ID =  [55 102 50 49 57 49 97 100 45 54 102 101 102 45 52 50 102 99 45 56 98 98 102 45 54 52 98 48 49 50 50 97 51 48 100 53]
2022/01/05 14:57:35 server/main:verifyKeyData() Entering
2022/01/05 14:57:35 clients/kbs/kbs:FetchKey() Entering
2022/01/05 14:57:35 clients/kbs/kbs:FetchKey() keyUrl: https://10.80.243.86:9443/kbs/v1/keys/7f2191ad-6fef-42fc-8bbf-64b0122a30d5/transfer
2022/01/05 14:57:36 pkg/wpm/util/fetch_key.go:FetchKey() Successfully retrieved key
2022/01/05 14:57:36 clients/kbs/kbs:FetchKey() https://10.80.243.86:9443/kbs/v1/keys/7f2191ad-6fef-42fc-8bbf-64b0122a30d5/transfer
2022/01/05 14:57:36 clients/kbs/kbs:FetchKey() Leaving
2022/01/05 14:57:36 server/main:verifyKeyData() New Key returned from KBS
2022/01/05 14:57:36 server/main:verifyKeyData() Leaving
time="2022-01-05T14:57:36Z" level=info msg="pkg/wpm/util/encrypt.go:Encrypt() Successfully unwrapped key" name=default pid=1
2022/01/05 14:57:36 server/main:NewCipher() Received key ID  onWKpZ4J0dODMmBdLHboTQ==
2022/01/05 14:57:36 server/main:NewCipher() Cipher address:=  0xb8218c80
2022/01/05 14:57:36 server/main:NewCipher() Cipher address in string:=  B8218C80
2022/01/05 14:57:36 server/main:NewCipher() Cipher address in byte:=  [66 56 50 49 56 67 56 48]
2022/01/05 14:57:36 server/main:NewCipher() Cipher again address in string:=  B8218C80
2022/01/05 14:57:36 server/main:NewCipher() Leaving
2022/01/05 14:57:37 server/main:NewGCM() Entering
2022/01/05 14:57:37 server/main:validateThisSession() Entering
2022/01/05 14:57:37 server/main:validateThisSession() Leaving
2022/01/05 14:57:37 server/main:NewGCM() Session ID received:  [15 102 242 205 44 121 189 51 23 33 0 73 202 27 108 85]
2022/01/05 14:57:37 server/main:NewGCM() Received cipher ID =  [66 56 50 49 56 67 56 48]
2022/01/05 14:57:37 server/main:NewGCM() Valid cipher address received
2022/01/05 14:57:37 server/main:NewGCM() Cipher pointer =  0xb8218c80
2022/01/05 14:57:37 server/main:NewGCM() Created gcm object =  0xb826e270
2022/01/05 14:57:37 server/main:NewGCM() Cipher address in string:=  B826E270
2022/01/05 14:57:37 server/main:NewGCM() Address in bytes:=  [66 56 50 54 69 50 55 48]
2022/01/05 14:57:37 server/main:NewGCM() Leaving
2022/01/05 14:57:37 server/main:NonceSize() Entering
2022/01/05 14:57:37 server/main:validateThisSession() Entering
2022/01/05 14:57:37 server/main:validateThisSession() Leaving
2022/01/05 14:57:37 server/main:NonceSize() Valid gcm address received
2022/01/05 14:57:37 server/main:NonceSize() Leaving
2022/01/05 14:57:37 server/main:Seal() Entering
2022/01/05 14:57:37 server/main:validateThisSession() Entering
2022/01/05 14:57:37 server/main:validateThisSession() Leaving
2022/01/05 14:57:37 server/main:Seal() Session ID received:  [15 102 242 205 44 121 189 51 23 33 0 73 202 27 108 85]
2022/01/05 14:57:37 server/main:Seal() Received gcm Object ID =  [66 56 50 54 69 50 55 48]
2022/01/05 14:57:37 server/main:Seal() Valid gcm address received
2022/01/05 14:57:37 server/main:Seal() Leaving
2022/01/05 14:57:37 server/main:NewCipher() Entering
2022/01/05 14:57:37 server/main:NewCipher() SessionID  D2byzSx5vTMXIQBJyhtsVQ==
2022/01/05 14:57:37 server/main:validateThisSession() Entering
2022/01/05 14:57:37 server/main:validateThisSession() Leaving
2022/01/05 14:57:37 server/main:NewCipher() Session id received:  [15 102 242 205 44 121 189 51 23 33 0 73 202 27 108 85]
2022/01/05 14:57:37 server/main:NewCipher() Received key ID =  [55 102 50 49 57 49 97 100 45 54 102 101 102 45 52 50 102 99 45 56 98 98 102 45 54 52 98 48 49 50 50 97 51 48 100 53]
2022/01/05 14:57:37 server/main:verifyKeyData() Entering
2022/01/05 14:57:37 server/main:verifyKeyData() Cached Key returned from SKC
2022/01/05 14:57:37 server/main:verifyKeyData() Leaving
time="2022-01-05T14:57:37Z" level=info msg="pkg/wpm/util/encrypt.go:Encrypt() Successfully unwrapped key" name=default pid=1
2022/01/05 14:57:37 server/main:NewCipher() Received key ID  onWKpZ4J0dODMmBdLHboTQ==
2022/01/05 14:57:37 server/main:NewCipher() Cipher address:=  0xb834c3d0
2022/01/05 14:57:37 server/main:NewCipher() Cipher address in string:=  B834C3D0
2022/01/05 14:57:37 server/main:NewCipher() Cipher address in byte:=  [66 56 51 52 67 51 68 48]
2022/01/05 14:57:37 server/main:NewCipher() Cipher again address in string:=  B834C3D0
2022/01/05 14:57:37 server/main:NewCipher() Leaving
2022/01/05 14:57:37 server/main:NewGCM() Entering
2022/01/05 14:57:37 server/main:validateThisSession() Entering
2022/01/05 14:57:37 server/main:validateThisSession() Leaving
2022/01/05 14:57:37 server/main:NewGCM() Session ID received:  [15 102 242 205 44 121 189 51 23 33 0 73 202 27 108 85]
2022/01/05 14:57:37 server/main:NewGCM() Received cipher ID =  [66 56 51 52 67 51 68 48]
2022/01/05 14:57:37 server/main:NewGCM() Valid cipher address received
2022/01/05 14:57:37 server/main:NewGCM() Cipher pointer =  0xb834c3d0
2022/01/05 14:57:37 server/main:NewGCM() Created gcm object =  0xb834c6f0
2022/01/05 14:57:37 server/main:NewGCM() Cipher address in string:=  B834C6F0
2022/01/05 14:57:37 server/main:NewGCM() Address in bytes:=  [66 56 51 52 67 54 70 48]
2022/01/05 14:57:37 server/main:NewGCM() Leaving
2022/01/05 14:57:38 server/main:NonceSize() Entering
2022/01/05 14:57:38 server/main:validateThisSession() Entering
2022/01/05 14:57:38 server/main:validateThisSession() Leaving
2022/01/05 14:57:38 server/main:NonceSize() Valid gcm address received
2022/01/05 14:57:38 server/main:NonceSize() Leaving
2022/01/05 14:57:38 server/main:Open() Entering
2022/01/05 14:57:38 server/main:validateThisSession() Entering
2022/01/05 14:57:38 server/main:validateThisSession() Leaving
2022/01/05 14:57:38 server/main:Open() session id received:  [15 102 242 205 44 121 189 51 23 33 0 73 202 27 108 85]
2022/01/05 14:57:38 server/main:Open() received gcm Object ID =  [66 56 50 54 69 50 55 48]
2022/01/05 14:57:38 server/main:Open() Valid gcm address received
2022/01/05 14:57:38 server/main:Open() Leaving
2022/01/05 14:57:39 server/main:Session() Entering
2022/01/05 14:57:39 server/main:Session() Leaving
2022/01/05 14:57:39 server/main:NewCipher() Entering
2022/01/05 14:57:39 server/main:NewCipher() SessionID  jp/ONz6jT9nahKbfqNIQJg==
2022/01/05 14:57:39 server/main:validateThisSession() Entering
2022/01/05 14:57:39 server/main:validateThisSession() Leaving
2022/01/05 14:57:39 server/main:NewCipher() Session id received:  [142 159 206 55 62 163 79 217 218 132 166 223 168 210 16 38]
2022/01/05 14:57:39 server/main:NewCipher() Received key ID =  [55 102 50 49 57 49 97 100 45 54 102 101 102 45 52 50 102 99 45 56 98 98 102 45 54 52 98 48 49 50 50 97 51 48 100 53]
2022/01/05 14:57:39 server/main:verifyKeyData() Entering
2022/01/05 14:57:39 server/main:verifyKeyData() Cached Key returned from SKC
2022/01/05 14:57:39 server/main:verifyKeyData() Leaving
time="2022-01-05T14:57:39Z" level=info msg="pkg/wpm/util/encrypt.go:Encrypt() Successfully unwrapped key" name=default pid=1
2022/01/05 14:57:39 server/main:NewCipher() Received key ID  onWKpZ4J0dODMmBdLHboTQ==
2022/01/05 14:57:39 server/main:NewCipher() Cipher address:=  0xb834c2e0
2022/01/05 14:57:39 server/main:NewCipher() Cipher address in string:=  B834C2E0
2022/01/05 14:57:39 server/main:NewCipher() Cipher address in byte:=  [66 56 51 52 67 50 69 48]
2022/01/05 14:57:39 server/main:NewCipher() Cipher again address in string:=  B834C2E0
2022/01/05 14:57:39 server/main:NewCipher() Leaving
2022/01/05 14:57:39 server/main:NewGCM() Entering
2022/01/05 14:57:39 server/main:validateThisSession() Entering
2022/01/05 14:57:39 server/main:validateThisSession() Leaving
2022/01/05 14:57:39 server/main:NewGCM() Session ID received:  [142 159 206 55 62 163 79 217 218 132 166 223 168 210 16 38]
2022/01/05 14:57:39 server/main:NewGCM() Received cipher ID =  [66 56 51 52 67 50 69 48]
2022/01/05 14:57:39 server/main:NewGCM() Valid cipher address received
2022/01/05 14:57:39 server/main:NewGCM() Cipher pointer =  0xb834c2e0
2022/01/05 14:57:39 server/main:NewGCM() Created gcm object =  0xb826e130
2022/01/05 14:57:39 server/main:NewGCM() Cipher address in string:=  B826E130
2022/01/05 14:57:39 server/main:NewGCM() Address in bytes:=  [66 56 50 54 69 49 51 48]
2022/01/05 14:57:39 server/main:NewGCM() Leaving
2022/01/05 14:57:40 server/main:NonceSize() Entering
2022/01/05 14:57:40 server/main:validateThisSession() Entering
2022/01/05 14:57:40 server/main:validateThisSession() Leaving
2022/01/05 14:57:40 server/main:NonceSize() Valid gcm address received
2022/01/05 14:57:40 server/main:NonceSize() Leaving
2022/01/05 14:57:40 server/main:Seal() Entering
2022/01/05 14:57:40 server/main:validateThisSession() Entering
2022/01/05 14:57:40 server/main:validateThisSession() Leaving
2022/01/05 14:57:40 server/main:Seal() Session ID received:  [142 159 206 55 62 163 79 217 218 132 166 223 168 210 16 38]
2022/01/05 14:57:40 server/main:Seal() Received gcm Object ID =  [66 56 50 54 69 49 51 48]
2022/01/05 14:57:40 server/main:Seal() Valid gcm address received
2022/01/05 14:57:40 server/main:Seal() Leaving
2022/01/05 14:57:40 server/main:NewCipher() Entering
2022/01/05 14:57:40 server/main:NewCipher() SessionID  jp/ONz6jT9nahKbfqNIQJg==
2022/01/05 14:57:40 server/main:validateThisSession() Entering
2022/01/05 14:57:40 server/main:validateThisSession() Leaving
2022/01/05 14:57:40 server/main:NewCipher() Session id received:  [142 159 206 55 62 163 79 217 218 132 166 223 168 210 16 38]
2022/01/05 14:57:40 server/main:NewCipher() Received key ID =  [55 102 50 49 57 49 97 100 45 54 102 101 102 45 52 50 102 99 45 56 98 98 102 45 54 52 98 48 49 50 50 97 51 48 100 53]
2022/01/05 14:57:40 server/main:verifyKeyData() Entering
2022/01/05 14:57:40 server/main:verifyKeyData() Cached Key returned from SKC
2022/01/05 14:57:40 server/main:verifyKeyData() Leaving
time="2022-01-05T14:57:40Z" level=info msg="pkg/wpm/util/encrypt.go:Encrypt() Successfully unwrapped key" name=default pid=1
2022/01/05 14:57:40 server/main:NewCipher() Received key ID  onWKpZ4J0dODMmBdLHboTQ==
2022/01/05 14:57:40 server/main:NewCipher() Cipher address:=  0xb826e850
2022/01/05 14:57:40 server/main:NewCipher() Cipher address in string:=  B826E850
2022/01/05 14:57:40 server/main:NewCipher() Cipher address in byte:=  [66 56 50 54 69 56 53 48]
2022/01/05 14:57:40 server/main:NewCipher() Cipher again address in string:=  B826E850
2022/01/05 14:57:40 server/main:NewCipher() Leaving
2022/01/05 14:57:40 server/main:NewGCM() Entering
2022/01/05 14:57:40 server/main:validateThisSession() Entering
2022/01/05 14:57:40 server/main:validateThisSession() Leaving
2022/01/05 14:57:40 server/main:NewGCM() Session ID received:  [142 159 206 55 62 163 79 217 218 132 166 223 168 210 16 38]
2022/01/05 14:57:40 server/main:NewGCM() Received cipher ID =  [66 56 50 54 69 56 53 48]
2022/01/05 14:57:40 server/main:NewGCM() Valid cipher address received
2022/01/05 14:57:40 server/main:NewGCM() Cipher pointer =  0xb826e850
2022/01/05 14:57:40 server/main:NewGCM() Created gcm object =  0xb837e5f0
2022/01/05 14:57:40 server/main:NewGCM() Cipher address in string:=  B837E5F0
2022/01/05 14:57:40 server/main:NewGCM() Address in bytes:=  [66 56 51 55 69 53 70 48]
2022/01/05 14:57:40 server/main:NewGCM() Leaving
2022/01/05 14:57:40 server/main:NonceSize() Entering
2022/01/05 14:57:40 server/main:validateThisSession() Entering
2022/01/05 14:57:40 server/main:validateThisSession() Leaving
2022/01/05 14:57:40 server/main:NonceSize() Valid gcm address received
2022/01/05 14:57:40 server/main:NonceSize() Leaving
2022/01/05 14:57:40 server/main:Open() Entering
2022/01/05 14:57:40 server/main:validateThisSession() Entering
2022/01/05 14:57:40 server/main:validateThisSession() Leaving
2022/01/05 14:57:40 server/main:Open() session id received:  [142 159 206 55 62 163 79 217 218 132 166 223 168 210 16 38]
2022/01/05 14:57:40 server/main:Open() received gcm Object ID =  [66 56 50 54 69 49 51 48]
2022/01/05 14:57:40 server/main:Open() Valid gcm address received
2022/01/05 14:57:40 server/main:Open() Leaving
2022/01/05 14:57:42 server/main:Session() Entering
2022/01/05 14:57:42 server/main:Session() Leaving
2022/01/05 14:57:42 server/main:NewCipher() Entering
2022/01/05 14:57:42 server/main:NewCipher() SessionID  7s4RQ9mWOcDEbRH0WKAOXw==
2022/01/05 14:57:42 server/main:validateThisSession() Entering
2022/01/05 14:57:42 server/main:validateThisSession() Leaving
2022/01/05 14:57:42 server/main:NewCipher() Session id received:  [238 206 17 67 217 150 57 192 196 109 17 244 88 160 14 95]
2022/01/05 14:57:42 server/main:NewCipher() Received key ID =  [55 102 50 49 57 49 97 100 45 54 102 101 102 45 52 50 102 99 45 56 98 98 102 45 54 52 98 48 49 50 50 97 51 48 100 53]
2022/01/05 14:57:42 server/main:verifyKeyData() Entering
2022/01/05 14:57:42 server/main:verifyKeyData() Cached Key returned from SKC
2022/01/05 14:57:42 server/main:verifyKeyData() Leaving
time="2022-01-05T14:57:42Z" level=info msg="pkg/wpm/util/encrypt.go:Encrypt() Successfully unwrapped key" name=default pid=1
2022/01/05 14:57:42 server/main:NewCipher() Received key ID  onWKpZ4J0dODMmBdLHboTQ==
2022/01/05 14:57:42 server/main:NewCipher() Cipher address:=  0xb82e4370
2022/01/05 14:57:42 server/main:NewCipher() Cipher address in string:=  B82E4370
2022/01/05 14:57:42 server/main:NewCipher() Cipher address in byte:=  [66 56 50 69 52 51 55 48]
2022/01/05 14:57:42 server/main:NewCipher() Cipher again address in string:=  B82E4370
2022/01/05 14:57:42 server/main:NewCipher() Leaving
2022/01/05 14:57:42 server/main:NewGCM() Entering
2022/01/05 14:57:42 server/main:validateThisSession() Entering
2022/01/05 14:57:42 server/main:validateThisSession() Leaving
2022/01/05 14:57:42 server/main:NewGCM() Session ID received:  [238 206 17 67 217 150 57 192 196 109 17 244 88 160 14 95]
2022/01/05 14:57:42 server/main:NewGCM() Received cipher ID =  [66 56 50 69 52 51 55 48]
2022/01/05 14:57:42 server/main:NewGCM() Valid cipher address received
2022/01/05 14:57:42 server/main:NewGCM() Cipher pointer =  0xb82e4370
2022/01/05 14:57:42 server/main:NewGCM() Created gcm object =  0xb82e45e0
2022/01/05 14:57:42 server/main:NewGCM() Cipher address in string:=  B82E45E0
2022/01/05 14:57:42 server/main:NewGCM() Address in bytes:=  [66 56 50 69 52 53 69 48]
2022/01/05 14:57:42 server/main:NewGCM() Leaving
2022/01/05 14:57:42 server/main:NonceSize() Entering
2022/01/05 14:57:42 server/main:validateThisSession() Entering
2022/01/05 14:57:42 server/main:validateThisSession() Leaving
2022/01/05 14:57:42 server/main:NonceSize() Valid gcm address received
2022/01/05 14:57:42 server/main:NonceSize() Leaving
2022/01/05 14:57:42 server/main:Seal() Entering
2022/01/05 14:57:42 server/main:validateThisSession() Entering
2022/01/05 14:57:42 server/main:validateThisSession() Leaving
2022/01/05 14:57:42 server/main:Seal() Session ID received:  [238 206 17 67 217 150 57 192 196 109 17 244 88 160 14 95]
2022/01/05 14:57:42 server/main:Seal() Received gcm Object ID =  [66 56 50 69 52 53 69 48]
2022/01/05 14:57:42 server/main:Seal() Valid gcm address received
2022/01/05 14:57:42 server/main:Seal() Leaving
2022/01/05 14:57:43 server/main:NewCipher() Entering
2022/01/05 14:57:43 server/main:NewCipher() SessionID  7s4RQ9mWOcDEbRH0WKAOXw==
2022/01/05 14:57:43 server/main:validateThisSession() Entering
2022/01/05 14:57:43 server/main:validateThisSession() Leaving
2022/01/05 14:57:43 server/main:NewCipher() Session id received:  [238 206 17 67 217 150 57 192 196 109 17 244 88 160 14 95]
2022/01/05 14:57:43 server/main:NewCipher() Received key ID =  [55 102 50 49 57 49 97 100 45 54 102 101 102 45 52 50 102 99 45 56 98 98 102 45 54 52 98 48 49 50 50 97 51 48 100 53]
2022/01/05 14:57:43 server/main:verifyKeyData() Entering
2022/01/05 14:57:43 server/main:verifyKeyData() Cached Key returned from SKC
2022/01/05 14:57:43 server/main:verifyKeyData() Leaving
time="2022-01-05T14:57:43Z" level=info msg="pkg/wpm/util/encrypt.go:Encrypt() Successfully unwrapped key" name=default pid=1
2022/01/05 14:57:43 server/main:NewCipher() Received key ID  onWKpZ4J0dODMmBdLHboTQ==
2022/01/05 14:57:43 server/main:NewCipher() Cipher address:=  0xb837e9c0
2022/01/05 14:57:43 server/main:NewCipher() Cipher address in string:=  B837E9C0
2022/01/05 14:57:43 server/main:NewCipher() Cipher address in byte:=  [66 56 51 55 69 57 67 48]
2022/01/05 14:57:43 server/main:NewCipher() Cipher again address in string:=  B837E9C0
2022/01/05 14:57:43 server/main:NewCipher() Leaving
2022/01/05 14:57:43 server/main:NewGCM() Entering
2022/01/05 14:57:43 server/main:validateThisSession() Entering
2022/01/05 14:57:43 server/main:validateThisSession() Leaving
2022/01/05 14:57:43 server/main:NewGCM() Session ID received:  [238 206 17 67 217 150 57 192 196 109 17 244 88 160 14 95]
2022/01/05 14:57:43 server/main:NewGCM() Received cipher ID =  [66 56 51 55 69 57 67 48]
2022/01/05 14:57:43 server/main:NewGCM() Valid cipher address received
2022/01/05 14:57:43 server/main:NewGCM() Cipher pointer =  0xb837e9c0
2022/01/05 14:57:43 server/main:NewGCM() Created gcm object =  0xb81b0f50
2022/01/05 14:57:43 server/main:NewGCM() Cipher address in string:=  B81B0F50
2022/01/05 14:57:43 server/main:NewGCM() Address in bytes:=  [66 56 49 66 48 70 53 48]
2022/01/05 14:57:43 server/main:NewGCM() Leaving
2022/01/05 14:57:43 server/main:NonceSize() Entering
2022/01/05 14:57:43 server/main:validateThisSession() Entering
2022/01/05 14:57:43 server/main:validateThisSession() Leaving
2022/01/05 14:57:43 server/main:NonceSize() Valid gcm address received
2022/01/05 14:57:43 server/main:NonceSize() Leaving
2022/01/05 14:57:43 server/main:Open() Entering
2022/01/05 14:57:43 server/main:validateThisSession() Entering
2022/01/05 14:57:43 server/main:validateThisSession() Leaving
2022/01/05 14:57:43 server/main:Open() session id received:  [238 206 17 67 217 150 57 192 196 109 17 244 88 160 14 95]
2022/01/05 14:57:43 server/main:Open() received gcm Object ID =  [66 56 50 69 52 53 69 48]
2022/01/05 14:57:43 server/main:Open() Valid gcm address received
2022/01/05 14:57:43 server/main:Open() Leaving
2022/01/05 14:57:44 server/main:Session() Entering
2022/01/05 14:57:44 server/main:Session() Leaving
2022/01/05 14:57:45 server/main:NewCipher() Entering
2022/01/05 14:57:45 server/main:NewCipher() SessionID  IfHZGTaBHSeYd6idAghbIA==
2022/01/05 14:57:45 server/main:validateThisSession() Entering
2022/01/05 14:57:45 server/main:validateThisSession() Leaving
2022/01/05 14:57:45 server/main:NewCipher() Session id received:  [33 241 217 25 54 129 29 39 152 119 168 157 2 8 91 32]
2022/01/05 14:57:45 server/main:NewCipher() Received key ID =  [55 102 50 49 57 49 97 100 45 54 102 101 102 45 52 50 102 99 45 56 98 98 102 45 54 52 98 48 49 50 50 97 51 48 100 53]
2022/01/05 14:57:45 server/main:verifyKeyData() Entering
2022/01/05 14:57:45 server/main:verifyKeyData() Cached Key returned from SKC
2022/01/05 14:57:45 server/main:verifyKeyData() Leaving
time="2022-01-05T14:57:45Z" level=info msg="pkg/wpm/util/encrypt.go:Encrypt() Successfully unwrapped key" name=default pid=1
2022/01/05 14:57:45 server/main:NewCipher() Received key ID  onWKpZ4J0dODMmBdLHboTQ==
2022/01/05 14:57:45 server/main:NewCipher() Cipher address:=  0xb834c3b0
2022/01/05 14:57:45 server/main:NewCipher() Cipher address in string:=  B834C3B0
2022/01/05 14:57:45 server/main:NewCipher() Cipher address in byte:=  [66 56 51 52 67 51 66 48]
2022/01/05 14:57:45 server/main:NewCipher() Cipher again address in string:=  B834C3B0
2022/01/05 14:57:45 server/main:NewCipher() Leaving
2022/01/05 14:57:45 server/main:NewGCM() Entering
2022/01/05 14:57:45 server/main:validateThisSession() Entering
2022/01/05 14:57:45 server/main:validateThisSession() Leaving
2022/01/05 14:57:45 server/main:NewGCM() Session ID received:  [33 241 217 25 54 129 29 39 152 119 168 157 2 8 91 32]
2022/01/05 14:57:45 server/main:NewGCM() Received cipher ID =  [66 56 51 52 67 51 66 48]
2022/01/05 14:57:45 server/main:NewGCM() Valid cipher address received
2022/01/05 14:57:45 server/main:NewGCM() Cipher pointer =  0xb834c3b0
2022/01/05 14:57:45 server/main:NewGCM() Created gcm object =  0xb8512430
2022/01/05 14:57:45 server/main:NewGCM() Cipher address in string:=  B8512430
2022/01/05 14:57:45 server/main:NewGCM() Address in bytes:=  [66 56 53 49 50 52 51 48]
2022/01/05 14:57:45 server/main:NewGCM() Leaving
2022/01/05 14:57:45 server/main:NonceSize() Entering
2022/01/05 14:57:45 server/main:validateThisSession() Entering
2022/01/05 14:57:45 server/main:validateThisSession() Leaving
2022/01/05 14:57:45 server/main:NonceSize() Valid gcm address received
2022/01/05 14:57:45 server/main:NonceSize() Leaving
2022/01/05 14:57:45 server/main:Seal() Entering
2022/01/05 14:57:45 server/main:validateThisSession() Entering
2022/01/05 14:57:45 server/main:validateThisSession() Leaving
2022/01/05 14:57:45 server/main:Seal() Session ID received:  [33 241 217 25 54 129 29 39 152 119 168 157 2 8 91 32]
2022/01/05 14:57:45 server/main:Seal() Received gcm Object ID =  [66 56 53 49 50 52 51 48]
2022/01/05 14:57:45 server/main:Seal() Valid gcm address received
2022/01/05 14:57:45 server/main:Seal() Leaving

2022/01/05 15:27:47 server/main:NonceSize() Entering
2022/01/05 15:27:47 server/main:validateThisSession() Entering
2022/01/05 15:27:47 server/main:validateThisSession() Leaving
2022/01/05 15:27:47 server/main:NonceSize() Invalid gcm address received
2022/01/05 15:27:47 server/main:NonceSize() Leaving

2022/01/05 15:39:47 server/main:Open() Entering
2022/01/05 15:39:47 server/main:validateThisSession() Entering
2022/01/05 15:39:47 server/main:validateThisSession() Leaving
2022/01/05 15:39:47 server/main:Open() session id received:  [33 241 217 25 54 129 29 39 152 119 168 157 2 8 91 32]
2022/01/05 15:39:47 server/main:Open() received gcm Object ID =  [66 56 53 49 50 52 51 48]
2022/01/05 15:39:47 server/main:Open() Valid gcm address received
2022/01/05 15:39:47 server/main:Open() Leaving
panic: crypto/cipher: incorrect nonce length given to GCM

goroutine 972 [running]:
crypto/aes.(*gcmAsm).Open(0xb8452280, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0xb83da0a0, 0x4d, 0x50, ...)
        /usr/local/go/src/crypto/aes/aes_gcm.go:140 +0x654
main.(*server).Open(0xfdd698, 0xc0b040, 0xb8326000, 0xb8239340, 0x0, 0x0, 0x0)
        /root/g_test2/session_management/golang/server/main.go:335 +0x768
session_management/golang/golang.Golang_Open_Handler(0xae3a60, 0xfdd698, 0xc0b040, 0xb8326000, 0xb81c4240, 0x0, 0xc0b040, 0xb8326000, 0xb8310540, 0x6d)
        /root/g_test2/session_management/golang/golang/golang_grpc.pb.go:267 +0x214
google.golang.org/grpc.(*Server).processUnaryRPC(0xb824b180, 0xc10d00, 0xb8800a80, 0xb847c000, 0xb821f8f0, 0xf9f410, 0x0, 0x0, 0x0)
        /usr/local/pkg/mod/google.golang.org/grpc@v1.42.0/server.go:1282 +0x522
google.golang.org/grpc.(*Server).handleStream(0xb824b180, 0xc10d00, 0xb8800a80, 0xb847c000, 0x0)
        /usr/local/pkg/mod/google.golang.org/grpc@v1.42.0/server.go:1616 +0xd05
google.golang.org/grpc.(*Server).serveStreams.func1.2(0xb858a0d0, 0xb824b180, 0xc10d00, 0xb8800a80, 0xb847c000)
        /usr/local/pkg/mod/google.golang.org/grpc@v1.42.0/server.go:921 +0xa5
created by google.golang.org/grpc.(*Server).serveStreams.func1
        /usr/local/pkg/mod/google.golang.org/grpc@v1.42.0/server.go:919 +0x1fd

Thanks in advance 👍

-Vijay

Источник

Wondering how to resolve Kubernetes error “context deadline exceeded”? We can help you.

As part of our Server Management Services, we assist our customers with several Kubernetes queries.

Today, let us see how our Support techs proceed to resolve it.

How to resolve Kubernetes error “context deadline exceeded”?

The error ‘context deadline exceeded’ means that we ran into a situation where a given action was not completed in an expected timeframe.

Usually, issue occurs if Pods become stuck in Init status.

Typical error will look as shown below:

Warning FailedCreatePodSandBox 93s (x8 over 29m) kubelet, 97011e0a-f47c-4673-ace7-d6f74cde9934 Failed to create pod sandbox: rpc error: code = DeadlineExceeded desc = context deadline exceeded Normal SandboxChanged 92s (x8 over 29m) kubelet, 97011e0a-f47c-4673-ace7-d6f74cde9934 Pod sandbox changed, it will be killed and re-created.

You would see errors for containers from kubelet.stderr.log.

Example:

E0114 14:57:13.656196 9838 remote_runtime.go:128] StopPodSandbox "ca05be4d6453ae91f63fd3f240cbdf8b34377b3643883075a6f5e05001d3646b" from runtime service failed: rpc error: code = DeadlineExceeded desc = context deadline exceeded
...
E0114 14:57:13.656256 9838 kuberuntime_manager.go:901] Failed to stop sandbox {"docker" "ca05be4d6453ae91f63fd3f240cbdf8b34377b3643883075a6f5e05001d3646b"}
...
W0114 14:57:30.151650 9838 cni.go:331] CNI failed to retrieve network namespace path: cannot find network namespace for the terminated container "ca05be4d6453ae91f63fd3f240cbdf8b34377b3643883075a6f5e05001d3646b"

You can also validate the status of the node-agent-hyperbus by running the following nsxcli command from the node (as root):

sudo -i
/var/vcap/jobs/nsx-node-agent/bin/nsxcli

“at the nsx-cli prompt, enter”: get node-agent-hyperbus status

Expected output:

HyperBus status: Healthy

In this scenario you would see the following error instead:

% An internal error occurred

This causes a loop of DEL (delete) requests to the nsx-node-agent process

Today, let us see the simple steps followed by our Support techs to resolve it.

Restarting the nsx-node-agent process will workaround this issue:

— Use “bosh ssh” command to access the worker node

Then, run the below commands.

sudo -i
monit restart nsx-node-agent

— Wait for nsx-node-agent to restart: watch monit summary

This must resolve the issue.

[Stuck in between? We’d be glad to assist you]

Conclusion

In short, today we saw steps followed by our Support Techs resolve Kubernetes failed to start in docker desktop error.

PREVENT YOUR SERVER FROM CRASHING!

Never again lose customers to poor server speed! Let us help you.

Our server experts will monitor & maintain your server 24/7 so that it remains lightning fast and secure.

GET STARTED

Источник

Failed Create Pod Sandbox

Overview

Pods remain in Pending phase

This was on a Managed GKE cluster

Check RunBook Match

When you see these errors:

Type     Reason                  Age                     From     Message
  ----     ------                  ----                    ----     -------
  Warning  FailedSync              47m (x27 over 3h)       kubelet  error determining status: rpc error: code = DeadlineExceeded desc = context deadline exceeded
  Warning  FailedCreatePodSandBox  7m56s (x38 over 3h23m)  kubelet  Failed to create pod sandbox: rpc error: code = Unknown desc = failed to start sandbox container for pod "xxx": operation timeout: context deadline exceeded

Also noticed running kubectl top nodes

NAME                                                 CPU(cores)   CPU%   MEMORY(bytes)   MEMORY%
node-1-xxx   158m         16%    2311Mi          87%
node-2-xxx   111m         11%    1456Mi          55%
node-3-xxx   391m         41%    1662Mi          63%
node-4-xxx   169m         17%    2210Mi          83%
node-5-xxx   <unknown>   <unknown>   <unknown>   <unknown>

Also noticed node events showed the node was repeatedly restarting, ran kubectl describe node-5-xxx

Events:
  Type    Reason        Age                     From     Message
  ----    ------        ----                    ----     -------
  Normal  NodeNotReady  3m15s (x2344 over 10d)  kubelet  Node node-5-xxx status is now: NodeNotReady
  Normal  NodeReady     2m15s (x2345 over 49d)  kubelet  Node node-5-xxx status is now: NodeReady

Initial Steps Overview

  1. Investigate the failing pod

  2. Identify the node the pod is meant to be scheduled on

  3. Investigate the node

Detailed Steps

1) Investigate the failing pod

Check the logs of the pod:

$ kubectl logs pod-xxx

Check the events of the pod:

$ kubectl describe pod pod-xxx

2) Investigate the node the pod is meant to be scheduled on

Describe pod and see what node the pod is meant to be running on:

$ kubectl describe pod-xxx

Ouput will start with something like this, look for the “Node: » part:

Name:         pod-xxx
Namespace:    namespace-xxx
Priority:     0
Node:         node-xxx

3) Investigate the node

Check the resources of the nodes:

$ kubectl top nodes

Check the events of the node you identified the pod was meant to be scheduled on:

$ kubectl describe node node-xxx

Solutions List

A) Remove problematic node

Solutions Detail

The solution was to remove the problematic node, see more details below.

A) Remove problematic node

Check Resolution

Further Steps

  1. Create Extra Node

  2. Drain Problematic Node

  3. Delete Problematic Node

1) Create Extra Node

You may need to create a new node before draining this node. Just check with kubectl top nodes to see if the nodes have extra capacity to schedule your drained pods.

If you see you need an extra node before you drain the node, make sure to do so.

In our situation we were using Managed GKE cluster, so we added a new node via the console.

2) Drain Problematic Node

Once you are sure there is enough capacity amongst your remaining nodes to schedule the pods that are on the problematic node, then you can go ahead and drain the node.

$ kubectl drain node-xxx

3) Delete Problematic Node

Check once all scheduled pods have been drained off of the node.

$ kubectl get nodes

Once done you can delete the node:

$ kubectl delete node node-xxx

Further Information

Owner

Cari Liebenberg

comments powered by
Источник

Содержание

  1. docker swarm mode Error response from daemon: rpc error: code = 4 desc = context deadline exceeded #1189
  2. Comments
  3. rpc error: code = DeadlineExceeded desc = context deadline exceeded #12234
  4. Comments
  5. Error response from daemon: rpc error: code = 4 desc = context deadline exceeded #30925
  6. Comments
  7. docker swarm leave results in Error response from daemon: context deadline exceeded #34140
  8. Comments
  9. Error response from daemon: rpc error: code = 4 desc = context deadline exceeded #31758
  10. Comments

docker swarm mode Error response from daemon: rpc error: code = 4 desc = context deadline exceeded #1189

When I run this portainer service on swarm mode, the following error occurred

Error response from daemon: rpc error: code = 4 desc = context deadline exceeded

The text was updated successfully, but these errors were encountered:

Did you try to start another service using the CLI ? I think that this issue is related to Docker and not Portainer deployment.

Seems to happen occasionally when managing services: moby/moby#29087

i find out answer in this page
#31427

I got the same error when trying to join a swarm cluster as a worker Used 2 VMs from Google cloud for this..

Manager node was working fine ..docker info—> swarm did not give any errors. but when i try to join the worker nodes with the token .. i got this error «Error response from daemon: Timeout was reached before node joined. The attempt to join the swarm will continue in the background. Use the «docker info» command to see the current swarm status of your node. » while docker info showed me
«rpc error: code = DeadlineExceeded desc = context deadline exceeded in swarm error»

tried a lot of different things finally below solution worked.

solution. —>. i used «docker swarm init —force-new-cluster». in one of the vms i tried to join the as a worker.. and then i used «docker swarm leave —force» on the existing manager node .. and the joined that one as a worker to the newly created cluster. Other vm also also worked when tried to join as workers for the new cluster..

ubuntu — 18.04
docker version -20.10.17

Источник

rpc error: code = DeadlineExceeded desc = context deadline exceeded #12234

starting etcd cluster with 3 nodes failed. The first two node connected, but the third reports:

rpc error: code = DeadlineExceeded desc = context deadline exceeded

The text was updated successfully, but these errors were encountered:

Please provide more info if you are still having this issue.

version 3.4
execute «etcdctl endpoint health»
«error»: «rpc error: code = DeadlineExceeded desc = context deadline exceeded»,
«msg»: «retrying of unary invoker failed»,

I think I am hitting a similar issue:

Kubernetes version: 1.18.8

Etcd cluster with 3 members

etcdctl version: 3.4.13
API version: 3.4

Etcd logs show the following errors:

etcdctl reports all endpoints are healthy:

etcdctl —endpoints=https:// :2379,https:// :2379,https:// :2379 —cacert=/etc/kubernetes/pki/etcd/ca.crt —cert=/etc/kubernetes/pki/etcd/peer.crt —key=/etc/kubernetes/pki/etcd/peer.key endpoint health

https:// :2379 is healthy: successfully committed proposal: took = 22.183879ms
https:// :2379 is healthy: successfully committed proposal: took = 22.319905ms
https:// :2379 is healthy: successfully committed proposal: took = 24.610958ms

However, when I run etcdctl endpoint health on each cluster member I get:

Running etcdctl alarm list on each member also shows the same:

Источник

Error response from daemon: rpc error: code = 4 desc = context deadline exceeded #30925

Description

I have a fresh installation of Docker for Mac 1.13.1.
I was applying the beginner tutorial, the voting app chapter: https://github.com/docker/labs/blob/master/beginner/chapters/votingapp.md#31-deploying-the-app. When I tried the command:

I got this error:

Steps to reproduce the issue:

  1. git clone https://github.com/docker/example-voting-app.git
  2. cd example-voting-app
  3. docker swarm init
  4. docker stack deploy —compose-file docker-stack.yml vote

then you will get this error:

Expected to have:

Output of docker version :

Output of docker info :

The text was updated successfully, but these errors were encountered:

is there a workaround for this issue? I am hitting it quite often. It happens sometimes and sometimes it does not.

I’m getting the same error trying to deploy a stack with a single service for testing.
Getting Mar 04 00:29:22 d1 dockerd[313]: time=»2017-03-04T00:29:22.170075788+01:00″ level=error msg=»Handler for POST /v1.26/networks/create returned error: rpc error: code = 4 desc = context deadline exceeded» in the logs.

The same thing is happening from mac, and from the dockerd node itself (running docker 1.13 on arch).

How can we provide more relevant debug info for this issue?

same issue on Docker for Windows

Could be related to registry timeouts (#31427)

This is related to #29987. Specifically, our error reporting for failures kind of sucks. It’s in my queue to fix, just sort of low priority right now. That wouldn’t fix this problem but it would make it a lot easier for everyone involved to figure out what’s going on.

I had ssh sessions on the manager and the worker and got the error when executing docker stack services vote on the manager console.
I closed both ssh sessions and run the docker commands form the host console $(docker-machine env manager) .

This fixed the error for me.

This issue does not occur no more.
Thank you.

Источник

docker swarm leave results in Error response from daemon: context deadline exceeded #34140

I’m trying to remove a Docker Swarm Node, but I get
Error response from daemon: context deadline exceeded
— force results in the same issue.

Docker node ls shows the node as down but active.

I was able to remove the node by running
docker node rm node-name from a swarm manager.

I am able to docker-machine ssh in the node.

docker -v is Docker version 17.06.0-ce, build 02c1d87

‘lsb_release -a` is

What else can be done to troubleshoot this issue?

How can I manually force the node to be removed from swarm? If I delete the /swarm folder in Docker directory, will it do it?

UPDATE After about 30 minutes, docker swarm leave -f worked. This is alarming, which logs should I look up to help understand why this happened and what was the reason for the delay?

The text was updated successfully, but these errors were encountered:

This never worked for me. I am still facing the error. Any help here please?

The context deadline exceeded message usually indicates that you lost quorum (there’s no majority of managers available, and a majority is needed to make any change to the swarm cluster, including «removing nodes from the swarm» — see Raft consensus in swarm mode, and (Maintain the quorum of managers)[https://docs.docker.com/engine/swarm/admin_guide/#maintain-the-quorum-of-managers]).

  • If you’re running a two-manager setup (which you should never do, as it brings no fault tolerance, and actually doubles the probability you loose quorum), both managers need to be available.
  • If the node you’re trying to remove is a manager, the node needs to be demoted first, before you can remove it from the swarm
  • docker swarm leave only affects the «local» state of the node you’re running from (it destroys the local swarm state), but does not remove the node from the swarm. Because of this, it does not affect the number of expected managers to be present (other managers still expect that node to be there), so docker node demote / docker node rm is still needed.

Please keep in mind that the GitHub issue tracker is not intended as a general support forum,
but for reporting bugs and feature requests. For other type of questions, consider using one of;

I’m closing this issue because this is a support question. If you suspect there’s a bug at hand, and you can reproduce on a current version of Docker, please open an issue with the information that’s requested in the issue template.

Источник

Error response from daemon: rpc error: code = 4 desc = context deadline exceeded #31758

Description

I’ve got a test environment for Docker Swarm Mode locally on my machine, conforming to the setup of this Docker Lab. The setup is made up of 3 manager as well as 3 worker nodes.
When trying to restart the existing swarm with all machines in stopped state, docker node ls is running into a timeout when I start with bringing back the leading manager node (let’s call it manager1) to life via Docker Machine. The error message I get is:
Error response from daemon: rpc error: code = 4 desc = context deadline exceeded

The other node’s machines are still disabled at this point. The interesting thing is that as soon as I start another one of the remaining manager nodes (manager2 or manager3) and repeat the command on manager1 (leader) afterwards, it works as expected and gives me output like this:

Even if I now decide to shutdown manager2 again, everything keeps working fine. I’m not sure if that’s a bug at all or if re-initializing the Raft cluster simply needs a majority of available managers (2 in this case) for being able to return into operating state.
Moreover, I made an interesting observation examining the output of docker info before and after restarting a second manager. With only manager1 running and getting the described error message, the Raft section of the docker info output says:

Along with the error message, that makes totally sense.
After having started manager2 (error vanished):

Steps to reproduce the issue:

  1. Create a swarm including 3 managers and 3 workers as described [here].(https://github.com/docker/labs/tree/master/swarm-mode/beginner-tutorial)
  2. Shutdown every single machine with docker-machine stop manager1 (repeat for all machines) without explicitly leaving the existing swarm.
  3. Make sure that every machine has been shut down.
  4. Now start the manager node which has been the Raft leader with docker-machine start manager1 .
  5. Connect to the restarted leader node via SSH and execute docker node ls . You should get the error message I described.
  6. Now, start a second manager node (manager2 for me), which has been a follower before.
  7. After the follower is back online, reconnect to the leader node and run docker node ls again. Alternatively, you can also execute this command on the follower node, which should not make any difference.
  8. You should now see a proper list of six manager and worker nodes, showing that two managers are currently ready and reachable.
  9. Shutdown the second manager you started in step 6 via Docker Machine (here: manager2) and execute docker node ls again on manager1. Again, you should get a list of nodes, showing that only manager1 is currently ready and reachable.

Expected results:
Instead of facing an error message after only the leading manager node has come back online, I’d expect the same output concerning the cluster state I get after starting another manager node, i.e.:

Output of docker version :

Output of docker info :

Additional environment details (AWS, VirtualBox, physical, etc.):

  • OS: Linux Mint 17.3 (rosa)
  • Linux Kernel: 3.19.0-32-generic
  • Docker Machine: docker-machine version 0.7.0, build a650a40
  • Boot2Docker version: 17.03.0-ce
  • VirtualBox Version 5.1.16 r113841

The text was updated successfully, but these errors were encountered:

Источник

Источник

Понравилась статья? Поделить с друзьями:
  • Rpc call error
  • Royal quest ошибка mafss initialization error
  • Royal quest create device error
  • Royal clima кассетный кондиционер ошибка e9
  • Rome total war ошибка rome total war при запуске