Missing value for atKey

[sachins-geekyants]

Lead: @sachins-geekyants

Describe the bug while fetching value for atKey, data was missing. Form @ minorgettingplayed7 , I sent some files to @ significantredpanda. We are able to fetch the atKeys on receiver's end but value is coming as "".

This is one of the key that is failing. cached:@significantredpanda:file_transfer_143d3c8a-7092-4bb8-a6e3-f846efce17b4.mospherepro@minorgettingplayed7

error message flutter: SEVERE|2022-01-25 14:30:39.657492|AtClientImpl|Decryption failed. encryption value is null for file_transfer_143d3c8a-7092-4bb8-a6e3-f846efce17b4.mospherepro

To Reproduce Steps to reproduce the behavior:

1. Onboard with @ significantredpanda
2. Try to get received file transfer data and check the AtValue.value

Expected behavior AtValue.value should give the actual data instead of "".

Were you using an @‎application when the bug was found?

• @ mosphere pro

[sitaram-kalluri]

Had call with @sachins-geekyants and below are the initial analysis from the secondary server logs. Looks like when running TTR job if empty data is received, the keys are updated with empty data.

bd07fcc6-0147-52fb-b1e2-5050f27e88d6_secondary.1.o2jgq3kqzkb0@hornet-12    | FINER|2022-01-25 08:00:05.163903|OutboundClient|writing to outbound connect
ion: lookup:file_transfer_143d3c8a-7092-4bb8-a6e3-f846efce17b4.mospherepro@minorgettingplayed7
bd07fcc6-0147-52fb-b1e2-5050f27e88d6_secondary.1.o2jgq3kqzkb0@hornet-12    |  
bd07fcc6-0147-52fb-b1e2-5050f27e88d6_secondary.1.o2jgq3kqzkb0@hornet-12    | 
bd07fcc6-0147-52fb-b1e2-5050f27e88d6_secondary.1.o2jgq3kqzkb0@hornet-12    | FINER|2022-01-25 08:00:10.265871|OutboundClient|lookup result after format:
  
bd07fcc6-0147-52fb-b1e2-5050f27e88d6_secondary.1.o2jgq3kqzkb0@hornet-12    | 
bd07fcc6-0147-52fb-b1e2-5050f27e88d6_secondary.1.o2jgq3kqzkb0@hornet-12    | FINEST|2022-01-25 08:00:10.266120|AtRefreshJob|lookup value of file_transfe
r_143d3c8a-7092-4bb8-a6e3-f846efce17b4.mospherepro@minorgettingplayed7 is  
bd07fcc6-0147-52fb-b1e2-5050f27e88d6_secondary.1.o2jgq3kqzkb0@hornet-12    | 
bd07fcc6-0147-52fb-b1e2-5050f27e88d6_secondary.1.o2jgq3kqzkb0@hornet-12    | FINEST|2022-01-25 08:00:10.266980|HiveKeystore|hive key:cached:@significant
redpanda:file_transfer_143d3c8a-7092-4bb8-a6e3-f846efce17b4.mospherepro@minorgettingplayed7 
bd07fcc6-0147-52fb-b1e2-5050f27e88d6_secondary.1.o2jgq3kqzkb0@hornet-12    | 
bd07fcc6-0147-52fb-b1e2-5050f27e88d6_secondary.1.o2jgq3kqzkb0@hornet-12    | FINEST|2022-01-25 08:00:10.267044|HiveKeystore|hive value:AtData{data: , me
taData: {createdBy: null, updatedBy: null, createdAt: 2022-01-21 08:35:17.659Z, updatedAt: 2022-01-25 08:00:10.266976Z, availableAt: null, expiresAt: 20
22-02-24 08:00:10.266Z, refreshAt: null, status: active, version: 1, ttl: 2592000000, ttb: null, ttr: -1, ccd: false, isBinary: null, isEncrypted: null,
 dataSignature: null}```

[sachins-geekyants]

@kalluriramkumar we are still facing this issue, do we have any update on this ?

[sitaram-kalluri]

@sachins-geekyants: we will take this issue into coming sprint(PR-30).

[yahu1031]

FINEST|2022-02-16 12:04:00.006821|AtRefreshJob|Scheduled Refresh Job started 

FINER|2022-02-16 12:04:15.722007|OutboundClient|handShakeResult: @murali@ 

FINER|2022-02-16 12:04:15.722333|AtRefreshJob|connect result: true 

FINER|2022-02-16 12:04:15.723894|OutboundClient|writing to outbound connection: lookup:key1@sitaram
 

FINER|2022-02-16 12:04:15.776405|OutboundClient|lookup result after format: data:value1_1 

FINEST|2022-02-16 12:04:21.779640|AtRefreshJob|key1@sitaram cached value is same as looked-up value. Not updating the cached key 

FINER|2022-02-16 12:04:24.388587|OutboundClientManager|retrieved outbound client from pool to @sitaram 

FINER|2022-02-16 12:04:24.392218|OutboundClient|writing to outbound connection: lookup:key2@sitaram
 

FINER|2022-02-16 12:04:29.496313|OutboundClient|lookup result after format:  

FINEST|2022-02-16 12:04:34.339313|AtRefreshJob|value not found for key2@sitaram. Failed updating the cached key 

FINEST|2022-02-16 12:04:38.276458|AtRefreshJob|scheduled Refresh Job completed 

Logs after the fix was done.

[sitaram-kalluri]

Following PR fixes this issue.

[murali-shris]

@kalluriramkumar removing fixed label until changes are published

[murali-shris]

fix published in at_client version 3.0.10

[sachins-geekyants]

I am running @ mospherePro with at_client:3.0.13

I can still reproduce this issue.

The following key was sent by significantredpanda to dying36dragonfly on 9th march 2022. On receiver's end data is coming as "".

data:{“key”:“cached:@dying36dragonfly:file_transfer_6284349d-7921-40d5-9c08-cca9e786f99a.mospherepro@significantredpanda”,“data”:“”,“metaData”:{“createdBy”:null,“updatedBy”:null,“createdAt”:“2022-03-11 07:56:29.485Z”,“updatedAt”:“2022-03-11 07:56:29.485Z”,“availableAt”:null,“expiresAt”:“2022-04-10 07:56:29.485Z”,“refreshAt”:null,“status”:“active”,“version”:0,“ttl”:2592000000,“ttb”:null,“ttr”:-1,“ccd”:false,“isBinary”:null,“isEncrypted”:null,“dataSignature”:null}}

[sitaram-kalluri]

I am running @ mospherePro with at_client:3.0.13

I can still reproduce this issue.

The following key was sent by significantredpanda to dying36dragonfly on 9th march 2022. On receiver's end data is coming as "".

data:{“key”:“cached:@dying36dragonfly:file_transfer_6284349d-7921-40d5-9c08-cca9e786f99a.mospherepro@significantredpanda”,“data”:“”,“metaData”:{“createdBy”:null,“updatedBy”:null,“createdAt”:“2022-03-11 07:56:29.485Z”,“updatedAt”:“2022-03-11 07:56:29.485Z”,“availableAt”:null,“expiresAt”:“2022-04-10 07:56:29.485Z”,“refreshAt”:null,“status”:“active”,“version”:0,“ttl”:2592000000,“ttb”:null,“ttr”:-1,“ccd”:false,“isBinary”:null,“isEncrypted”:null,“dataSignature”:null}}

The secondary server is restarted on 11th March and unable to fetch the earlier logs. Requested to @sachins-geekyants to share the files today and captured the id's. Will keep an eye on the server logs.

[sachins-geekyants]

Can still see this issue for ID: cached:@dying36dragonfly:file_transfer_2b3b7446-7003-40f0-a78c-8f2ad1e00514.mospherepro@significantredpanda

had a discussion with Sitaram, he pointed

data: [{"id":"7","name":"secondaryServerVersion","value":"3.0.10"}] For some reason the secondary server is running on 3.0.10 version we have the fix on 3.0.12 version. Hence you are still seeing the issue

[sitaram-kalluri]

Can still see this issue for ID: cached:@dying36dragonfly:file_transfer_2b3b7446-7003-40f0-a78c-8f2ad1e00514.mospherepro@significantredpanda

had a discussion with Sitaram, he pointed

data: [{"id":"7","name":"secondaryServerVersion","value":"3.0.10"}] For some reason the secondary server is running on 3.0.10 version we have the fix on 3.0.12 version. Hence you are still seeing the issue

@sachins-geekyants : Even if the server is upgraded to a new version, the key will not have the old value because, as far as i remember app does not store the key (setting sharedWith to dying36dragonfly in significantredpanda atSign)

[sachins-geekyants]

We can not recover the old value but if the server is upgraded to 3.0.12 version, we should not be seeing this issue?

[sitaram-kalluri]

We can not recover the old value but if the server is upgraded to 3.0.12 version, we should not be seeing this issue?

@sachins-geekyants : Correct.

[sachins-geekyants]

Similar issue was observed on different atsign as well - 5distinctiveaquabike

data:{“key”:“cached:@5distinctiveaquabike:file_transfer_0731d300-06e4-4d60-94d9-8e5ed92e2577.mospherepro@jetskiracingpetite”,“data”:“”,“metaData”:{“createdBy”:null,“updatedBy”:null,“createdAt”:“2022-03-31 09:01:11.246Z”,“updatedAt”:“2022-03-31 09:01:11.247Z”,“availableAt”:null,“expiresAt”:“2022-04-30 09:01:11.247Z”,“refreshAt”:null,“status”:“active”,“version”:0,“ttl”:2592000000,“ttb”:null,“ttr”:-1,“ccd”:false,“isBinary”:null,“isEncrypted”:null,“dataSignature”:null,“sharedKeyEnc”:null,“pubKeyCS”:null}}

[sachins-geekyants]

@kalluriramkumar This happened again on atsigns whose servers are updated(curiousrazzledazzlerose , 5distinctiveaquabike).

data:{"key":"cached:@curiousrazzledazzlerose:file_transfer_00660614-602d-4c8d-9042-338439e34803.mospherepro@5distinctiveaquabike","data":"","metaData":{"createdBy":null,"updatedBy":null,"createdAt":"2022-04-07 14:21:33.795Z","updatedAt":"2022-04-07 14:21:33.795Z","availableAt":null,"expiresAt":"2022-04-22 14:21:33.795Z","refreshAt":null,"status":"active","version":0,"ttl":1296000000,"ttb":null,"ttr":-1,"ccd":false,"isBinary":null,"isEncrypted":null,"dataSignature":null,"sharedKeyEnc":null,"pubKeyCS":null}}

[sitaram-kalluri]

The value of the key is changed before the server is updated to the latest version. From the logs, the key is updated at 2022-04-07 06:00:36.348092 and the server is updated at 2022-04-07 07:58:11

Log snippet of key update

f2d60436-eca2-597f-9a6a-df5d8c2f8325_secondary.1.smxyer0m34e5@swarm0001-09.us-central1-c.c.secondaries.internal | FINER|2022-04-07 06:00:31.246278|OutboundClient|writing to outbound connection: lookup:file_transfer_00660614-602d-4c8d-9042-338439e34803.mospherepro@5distinctiveaquabike f2d60436-eca2-597f-9a6a-df5d8c2f8325_secondary.1.smxyer0m34e5@swarm0001-09.us-central1-c.c.secondaries.internal | FINEST|2022-04-07 06:00:36.347071|AtRefreshJob|lookup value of file_transfer_00660614-602d-4c8d-9042-338439e34803.mospherepro@5distinctiveaquabike is f2d60436-eca2-597f-9a6a-df5d8c2f8325_secondary.1.smxyer0m34e5@swarm0001-09.us-central1-c.c.secondaries.internal | FINEST|2022-04-07 06:00:36.348092|HiveKeystore|hive key:cached:@curiousrazzledazzlerose:file_transfer_00660614-602d-4c8d-9042-338439e34803.mospherepro@5distinctiveaquabike

Log snippet of server update

f2d60436-eca2-597f-9a6a-df5d8c2f8325_secondary.1.j8zp9fwev6ky@swarm0001-09.us-central1-c.c.secondaries.internal | INFO|2022-04-07 07:58:10.776076|AtS econdaryServer|currentAtSign : @curiousrazzledazzlerose f2d60436-eca2-597f-9a6a-df5d8c2f8325_secondary.1.j8zp9fwev6ky@swarm0001-09.us-central1-c.c.secondaries.internal | INFO|2022-04-07 07:58:11.264119|AtS econdaryServer|Secondary server started on version : 3.0.14 on root server : root.atsign.org

[gkc]

Assigning myself to this for PR56 as I will be adding multiple tests for the refresh job and ensuring that it works correctly, and continues to work correctly in the future.

[gkc]

Can no longer reproduce