search

encointer / encointer-worker

SubstraTEE worker for encointer-node-teeproxy
Apache License 2.0
3 stars 4 forks source link

Cantillon tutorial fails at registering attestations #26

Closed brenzi closed 4 years ago

brenzi commented 4 years ago

CLI hangs at 

nctr trusted register-attestations $account1 $witness2_1 $witness3_1 --mrenclave $MRENCLAVE --shard $cid

and also get-attestations query confirms that the attestations were not registered

nctr trusted get-attestations $account1 --mrenclave $MRENCLAVE --shard $cid

Here the worker log for register-attestations followed by get-attestation

Aug 27 10:40:10 devsgx03 encointer-worker[17455]: [2020-08-27T08:40:10Z DEBUG substratee_worker_enclave] Scanning block 1189036 for relevant xt
Aug 27 10:40:10 devsgx03 encointer-worker[17455]: [2020-08-27T08:40:10Z INFO  substratee_worker_enclave] Found CallWorker extrinsic in block:
Aug 27 10:40:10 devsgx03 encointer-worker[17455]:     Call: [6, 2]
Aug 27 10:40:10 devsgx03 encointer-worker[17455]:     Request:
Aug 27 10:40:10 devsgx03 encointer-worker[17455]:     shard: BHGpQExSEVQc8bN3nzLQZ8Vj3kwTvHigFejjRKpNBRJQ
Aug 27 10:40:10 devsgx03 encointer-worker[17455]:     cyphertext: [34, 95, 241, 146, 127, 186, 1, 164, 137, 68, 63, 215, 204, 133, 94, 58, 17, 41, 159, 118, 178, 70, 169, 7, 121, 174, 231, 86, 1, 203, 214, 120, 218, 111, 192, 126, 113, 48, 136, 183, 96, 134, 70, 56, 140, 97, 210, 114, 190, 29, 160, 126, 79, 172, 205, 54, 167, 32, 77, 129, 12, 35, 189, 182, 75, 241, 254, 197, 11, 5, 197, 207, 45, 12, 167, 14, 42, 232, 28, 195, 202, 131, 131, 219, 71, 238, 208, 222, 70, 187, 54, 42, 158, 46, 92, 200, 102, 251, 213, 228, 196, 192, 93, 116, 188, 241, 216, 206, 203, 27, 108, 181, 125, 13, 73, 60, 21, 105, 44, 112, 253, 185, 0, 101, 93, 119, 156, 172, 89, 101, 250, 134, 134, 16, 220, 149, 59, 218, 232, 214,
90, 250, 185, 168, 130, 47, 157, 86, 72, 145, 131, 91, 107, 201, 129, 42, 248, 29, 41, 108, 163, 211, 128, 141, 139, 140, 252, 189, 238, 240, 115, 31, 231, 41, 53, 113, 10, 157, 37, 33, 48, 162, 74, 73, 129, 227, 62, 11, 147, 87, 208, 204, 96, 253, 216, 68, 180, 13, 242, 157, 45, 27, 95, 3, 19, 222, 165, 114, 57, 44, 12, 76, 243, 227, 36, 169, 19, 85, 107, 93, 97, 119, 183, 192, 86, 225, 139, 5, 74, 223, 142, 78, 12, 4, 113, 99, 14, 166, 89, 253, 140, 207, 122, 8, 208,
96, 250, 82, 221, 36, 19, 152, 74, 164, 75, 94, 126, 113, 112, 35, 124, 102, 176, 115, 58, 47, 133, 59, 234, 250, 249, 21, 219, 181, 51, 206, 157, 86, 81, 9, 232, 253, 47, 19, 171, 212, 246, 128, 17, 222, 168, 29, 254, 177, 193, 120, 240, 78, 34, 79, 77, 206, 220, 22, 240, 133, 232, 32, 92, 184, 131, 197, 105, 82, 223, 134, 139, 75, 30, 89, 60, 99, 134, 180, 231, 239, 234, 88, 77, 10, 176, 69, 192, 125, 218, 102, 70, 18, 35, 198, 242, 26, 75, 180, 48, 126, 248, 165, 153, 52, 163, 172, 6, 234, 43, 55, 171, 144, 58, 38, 34, 164, 158, 176, 6, 43, 143, 1, 178, 77, 32, 72, 170, 103, 153, 34, 87, 64, 164, 117, 39, 138, 227, 26, 70, 23, 148, 235, 66, 167, 108, 62, 150, 222, 127, 123, 232, 18, 81, 28, 241, 253, 6, 141, 65, 238, 193, 109, 157, 84, 160, 24, 240, 249, 139, 66, 252, 150, 29, 28, 151, 81, 157, 180, 24, 158, 154, 181, 142, 178, 209, 200, 238, 66, 126, 222, 130, 227, 110, 28, 40, 108, 168, 184, 194, 101, 160, 135, 252, 206, 182, 45, 132, 112, 208, 108, 228, 55, 171, 202, 108, 46, 185, 60, 180, 126, 106, 185, 200, 104, 95, 6, 82, 142, 153, 193, 143, 231, 63, 247, 160, 169, 183, 41, 143, 142, 52, 147, 239, 223, 181, 26, 187, 112, 159, 46, 255, 83, 158, 203, 164, 157, 2, 2, 21, 103, 27, 148, 26, 137, 228, 216, 59, 29, 158, 142, 138, 31, 121, 185, 4, 151, 223, 132, 42, 251, 184, 79, 17, 88, 191, 233, 0, 121, 163, 154, 197, 238, 179, 18, 109, 55, 233, 219, 77, 191, 197, 159, 5, 87, 65, 179, 131, 109, 8, 230, 14, 237, 171, 105, 32, 151, 219, 227, 143, 4, 12, 164, 231, 139, 200, 177, 153, 235, 0, 130, 120, 0, 184, 20, 213, 172, 156, 57, 128, 172, 59, 112, 139, 16, 62, 21, 194, 141, 234, 52, 139, 167, 93, 211, 243, 29, 117, 160, 112, 102, 209, 95, 180, 124, 88, 153, 49, 89, 156, 219, 146, 40, 149, 104, 144, 97, 187, 166, 23, 53, 248, 237, 18, 117, 58, 203, 246, 76, 117, 25, 133, 93, 10, 152, 150, 255, 14, 131, 78, 252, 185, 189, 255, 212, 238, 193, 38, 164, 22, 226, 158, 204, 241, 155, 70, 178, 88, 8, 217, 112, 20, 235, 99, 75, 189, 79, 122, 8, 179, 52, 70, 91, 22, 169, 73, 51, 163, 235, 145, 27, 47, 74, 57, 189, 168, 41, 220, 110, 39, 49, 176, 48, 11, 236, 37, 22, 226, 156, 88, 213, 220, 33, 130, 139, 152, 50, 74, 200, 146, 67, 174, 122, 228, 113, 79, 148, 69, 236, 197, 212, 50, 148, 137, 63, 175, 82, 97, 97, 16, 9, 230, 150, 66, 141, 10, 37, 246, 137, 189, 83, 112, 199, 102, 198, 158, 101, 132, 216, 49, 185, 211, 217, 229, 191, 56,
77, 144, 21, 165, 47, 83, 220]
Aug 27 10:40:10 devsgx03 encointer-worker[17455]: [2020-08-27T08:40:10Z DEBUG substratee_worker_enclave] decrypt the call
Aug 27 10:40:10 devsgx03 encointer-worker[17455]: [2020-08-27T08:40:10Z DEBUG substratee_worker_enclave] query mrenclave of self
Aug 27 10:40:10 devsgx03 encointer-worker[17455]: [2020-08-27T08:40:10Z DEBUG substratee_worker_enclave::attestation]     [Enclave] EPID group id = [173, 11, 0, 0]
Aug 27 10:40:10 devsgx03 encointer-worker[17455]: [2020-08-27T08:40:10Z DEBUG substratee_worker_enclave::attestation]     [Enclave] Report creation successful. mr_signer.m = [131, 215, 25, 231, 125, 234, 202, 20, 112, 246, 186, 246, 42,
77, 119, 67, 3, 200, 153, 219, 105, 2, 15, 156, 112, 238, 29, 252, 8, 199, 206, 158]
Aug 27 10:40:10 devsgx03 encointer-worker[17455]: [2020-08-27T08:40:10Z DEBUG substratee_worker_enclave] MRENCLAVE of self is E9h2hi91jn8Y9taz3JynF82sLkaUREY13XAhRWeu1fiR
Aug 27 10:40:10 devsgx03 encointer-worker[17455]: [2020-08-27T08:40:10Z DEBUG substratee_worker_enclave::state] State loaded from ./shards/BHGpQExSEVQc8bN3nzLQZ8Vj3kwTvHigFejjRKpNBRJQ/state.bin with size 8006B, deserializing...
Aug 27 10:40:10 devsgx03 encointer-worker[17455]: [2020-08-27T08:40:10Z DEBUG substratee_worker_enclave] Update STF storage!
Aug 27 10:40:10 devsgx03 encointer-worker[17455]: [2020-08-27T08:40:10Z DEBUG substratee_worker_enclave] execute STF
Aug 27 10:40:10 devsgx03 encointer-worker[17455]: [2020-08-27T08:40:10Z ERROR substratee_worker_enclave] Error performing Stf::execute. Error: Dispatch("ceremonies_register_attestations")
Aug 27 10:40:10 devsgx03 encointer-worker[17455]: [2020-08-27T08:40:10Z DEBUG substratee_worker_enclave] Restored ECC pubkey:
Aug 27 10:40:10 devsgx03 encointer-worker[17455]: [2020-08-27T08:40:10Z DEBUG substratee_worker_enclave::io::light_validation] backup chain relay state
Aug 27 10:40:10 devsgx03 encointer-worker[17455]: [2020-08-27T08:40:10Z DEBUG substratee_worker_enclave::io::light_validation] Seal Chain Relay State. Current state: LightValidationTest { num_relays: 1, tracked_relays: {1: RelayInfo { last_finalized_block_header_number: 1189036, current_validator_set: [(<wasm:stripped>, 1), (<wasm:stripped>, 1)], current_validator_set_id: 0 amount of transaction in tx_inclusion_queue: 12 }} }
Aug 27 10:40:11 devsgx03 encointer-worker[17455]: [2020-08-27T08:40:11Z INFO  encointer_worker::ws_server] [WS Server] Forwarding message to worker event loop: Binary([2, 1, 3, 112, 226, 133, 171, 180, 63, 88, 241, 67, 243, 176, 101, 87, 224, 170, 235, 206, 139, 25, 71, 77, 212, 89, 125, 128, 156, 69, 130, 83, 80, 22, 92, 152, 192, 11, 253, 83, 216, 54, 98, 213, 71, 2, 42, 132, 22, 26, 252, 229, 9, 185, 88, 113, 101, 187, 167, 174, 56, 209, 160, 26, 176, 158, 17, 16, 58, 119, 153, 7, 239, 161, 108, 210, 165, 234, 247, 246, 52, 191, 32, 43, 118, 14, 160, 244, 185, 132, 93, 76, 134, 89, 35, 124, 89, 27, 3, 105, 73, 160, 15, 106, 215, 143, 85, 46, 4, 44, 66, 30, 179, 51, 142, 176, 236, 114, 85, 13, 162, 41, 144, 109, 25, 104, 62, 151, 80, 248, 135, 152, 192, 11, 253, 83, 216, 54, 98, 213, 71, 2, 42, 132, 22, 26, 252, 229, 9, 185, 88, 113, 101, 187, 167, 174, 56, 209, 160, 26, 176, 158, 17])
Aug 27 10:40:13 devsgx03 encointer-worker[17455]: Synced 1189037 blocks out of 1189037 finalized blocks
Aug 27 10:40:13 devsgx03 encointer-worker[17455]: [2020-08-27T08:40:13Z INFO  encointer_worker::ws_server]      [WS Server] Got message 'WsServerRequest { client: Sender { token: Token(0), channel: mio::channel::SyncSender<Command>, connection_id: 21 }, request: StfState(trusted(TrustedGetterSigned { getter: attestations(70e285abb43f58f143f3b06557e0aaebce8b19474dd4597d809c45825350165c (5EciWcYP...), 0x98c00bfd53d83662d547022a84161afce509b9587165bba7ae38d1a01ab09e11), signature: AnySignature(0x103a779907efa16cd2a5eaf7f634bf202b760ea0f4b9845d4c8659237c591b036949a00f6ad78f552e042c421eb3338eb0ec72550da229906d19683e9750f887) }), 0x98c00bfd53d83662d547022a84161afce509b9587165bba7ae38d1a01ab09e11) }'.
Aug 27 10:40:13 devsgx03 encointer-worker[17455]: [2020-08-27T08:40:13Z INFO  encointer_worker::ws_server]      [WS Server] Query state
Aug 27 10:40:13 devsgx03 encointer-worker[17455]: [2020-08-27T08:40:13Z DEBUG substratee_worker_enclave] verifying signature of TrustedGetterSigned
Aug 27 10:40:13 devsgx03 encointer-worker[17455]: [2020-08-27T08:40:13Z DEBUG substratee_worker_enclave::state] State loaded from ./shards/BHGpQExSEVQc8bN3nzLQZ8Vj3kwTvHigFejjRKpNBRJQ/state.bin with size 8006B, deserializing...
Aug 27 10:40:15 devsgx03 encointer-worker[17455]: [2020-08-27T08:40:15Z DEBUG substratee_worker_enclave] Update STF storage!
Aug 27 10:40:15 devsgx03 encointer-worker[17455]: [2020-08-27T08:40:15Z INFO  substratee_stf::sgx] No specific storage updates needed for getter. Returning those for on block: trusted(TrustedGetterSigned { getter: attestations(, 0x98c00bfd53d83662d547022a84161afce509b9587165bba7ae38d1a01ab09e11), signature: <wasm:stripped> })
Aug 27 10:40:15 devsgx03 encointer-worker[17455]: [2020-08-27T08:40:15Z DEBUG substratee_worker_enclave] calling into STF to get state
Aug 27 10:40:15 devsgx03 encointer-worker[17455]: [2020-08-27T08:40:15Z DEBUG substratee_worker_enclave] returning getter result
Aug 27 10:40:15 devsgx03 encointer-worker[17455]: [2020-08-27T08:40:15Z INFO  encointer_worker] Ignoring event EventRecord { phase: Phase::ApplyExtrinsic(0), event: Event::system(RawEvent::ExtrinsicSuccess(DispatchInfo { weight: 159000000, class: DispatchClass::Mandatory, pays_fee: Pays::Yes })), topics: [] }
Aug 27 10:40:15 devsgx03 encointer-worker[17455]: [2020-08-27T08:40:15Z INFO  encointer_worker::ws_server] [WS Server] WebSocket closing for (Normal)
Aug 27 10:40:15 devsgx03 encointer-worker[17455]: [2020-08-27T08:40:15Z DEBUG substratee_worker_enclave] Restored ECC pubkey:
Aug 27 10:40:15 devsgx03 encointer-worker[17455]: [2020-08-27T08:40:15Z INFO  encointer_worker] [+] Got ed25519 account of TEE = 5Eztpox9YRidTCReasMep5m7x3vvXSFpmbjfHhihw7QqNyZY
Aug 27 10:40:15 devsgx03 encointer-worker[17455]: [2020-08-27T08:40:15Z INFO  substratee_worker_enclave] Syncing chain relay!
Aug 27 10:40:17 devsgx03 encointer-worker[17455]: [2020-08-27T08:40:17Z DEBUG substratee_worker_enclave] Update STF storage upon block import!

So the enclave tells us:

Error performing Stf::execute. Error: Dispatch("ceremonies_register_attestations")
brenzi commented 4 years ago

could reproduce this starting all over from scratch

brenzi commented 4 years ago

Thanks to new debug messages there's some more info:

If we create claims during ASSIGNING phase, the meetup timestamp will be different than if we create the same claim during ATTESTING

generate during assigning
[2020-08-30T13:53:25Z DEBUG substratee_stf::cli] claim: ClaimOfAttendance { claimant_public: 50503350955afe8a107d6f115dc253eb5d75a3fe37a90b373db26cc12e3c6661 (5Dt1Wg85...), ceremony_index: 37, currency_identifier: 0x62b697d59a41ecd5edfa0a9f8a26913ebe84d4f80edc1c934be7b6f9f633b05f, meetup_index: 1, location: Location { lat: 35.8935002615, lon: 25.9397506714 }, timestamp: 1598955374460, number_of_participants_confirmed: 3 }
50503350955afe8a107d6f115dc253eb5d75a3fe37a90b373db26cc12e3c66612500000062b697d59a41ecd5edfa0a9f8a26913ebe84d4f80edc1c934be7b6f9f633b05f0100000000000000e26ebce423000000008093f0190000007cc72a497401000003000000

(GMT Tuesday, September 1, 2020 10:16:14.460 AM)

generate during attesting
[2020-08-30T13:58:45Z DEBUG substratee_stf::cli] claim: ClaimOfAttendance { claimant_public: 50503350955afe8a107d6f115dc253eb5d75a3fe37a90b373db26cc12e3c6661 (5Dt1Wg85...), ceremony_index: 37, currency_identifier: 0x62b697d59a41ecd5edfa0a9f8a26913ebe84d4f80edc1c934be7b6f9f633b05f, meetup_index: 1, location: Location { lat: 35.8935002615, lon: 25.9397506714 }, timestamp: 1598696174460, number_of_participants_confirmed: 3 }
50503350955afe8a107d6f115dc253eb5d75a3fe37a90b373db26cc12e3c66612500000062b697d59a41ecd5edfa0a9f8a26913ebe84d4f80edc1c934be7b6f9f633b05f0100000000000000e26ebce423000000008093f0190000007cb3b7397401000003000000

(GMT Saturday, August 29, 2020 10:16:14.460 AM)

this may be caused by fast-forwarding to next_phase() which affects meetup time.

when testing bot-community-sea-of-crete.sh, the runtime complains

[2020-08-30T14:16:07Z DEBUG sp_io::misc] ignoring claim beyond time tolerance (too early)
brenzi commented 4 years ago

some test logs

 on chain queries

phase=ATTESTING
next_phase_timestamp=1598832000000  (GMT Monday, August 31, 2020 12:00:00 AM)
phase_durations(ATTESTING)= 172800000 (48h)
cid = 37

---------------

AliceIncognito

[2020-08-30T14:21:22Z DEBUG substratee_stf::cli] claim: ClaimOfAttendance { claimant_public: 50503350955afe8a107d6f115dc253eb5d75a3fe37a90b373db26cc12e3c6661 (5Dt1Wg85...), ceremony_index: 37, currency_identifier: 0x62b697d59a41ecd5edfa0a9f8a26913ebe84d4f80edc1c934be7b6f9f633b05f, meetup_index: 1, location: Location { lat: 35.8935002615, lon: 25.9397506714 }, timestamp: 1598696174460, number_of_participants_confirmed: 3 }
claim1=50503350955afe8a107d6f115dc253eb5d75a3fe37a90b373db26cc12e3c66612500000062b697d59a41ecd5edfa0a9f8a26913ebe84d4f80edc1c934be7b6f9f633b05f0100000000000000e26ebce423000000008093f0190000007cb3b7397401000003000000

timestamp is      1598696174460 (GMT Saturday, August 29, 2020 10:16:14.460 AM)
onchain formula:  1598696160000 (14s earlier)
(rounding lon)

BobIncognito

[2020-08-30T14:22:11Z DEBUG substratee_stf::cli] claim: ClaimOfAttendance { claimant_public: c24c5b3969d8ec4ca8a655a98dcc136d5d4c29d1206ffe7721e80ebdfa1d0b77 (5GTTq4En...), ceremony_index: 37, currency_identifier: 0x62b697d59a41ecd5edfa0a9f8a26913ebe84d4f80edc1c934be7b6f9f633b05f, meetup_index: 1, location: Location { lat: 35.8935002615, lon: 25.9397506714 }, timestamp: 1598696174460, number_of_participants_confirmed: 3 }
claim2=c24c5b3969d8ec4ca8a655a98dcc136d5d4c29d1206ffe7721e80ebdfa1d0b772500000062b697d59a41ecd5edfa0a9f8a26913ebe84d4f80edc1c934be7b6f9f633b05f0100000000000000e26ebce423000000008093f0190000007cb3b7397401000003000000

CharlieIncognito

[2020-08-30T14:23:02Z DEBUG substratee_stf::cli] claim: ClaimOfAttendance { claimant_public: a0f90738cda701bb8c8506bb278488e6efe8549489ef4cc77ca4024efb42311b (5FhmVhGB...), ceremony_index: 37, currency_identifier: 0x62b697d59a41ecd5edfa0a9f8a26913ebe84d4f80edc1c934be7b6f9f633b05f, meetup_index: 1, location: Location { lat: 35.8935002615, lon: 25.9397506714 }, timestamp: 1598696174460, number_of_participants_confirmed: 3 }
claim3=a0f90738cda701bb8c8506bb278488e6efe8549489ef4cc77ca4024efb42311b2500000062b697d59a41ecd5edfa0a9f8a26913ebe84d4f80edc1c934be7b6f9f633b05f0100000000000000e26ebce423000000008093f0190000007cb3b7397401000003000000

then do all the signing

> export RUST_LOG=debug,ws=warn,substrate_api_client=warn
> nctr trusted register-attestations $account1 $witness2_1 $witness3_1 --mrenclave $MRENCLAVE --shard $cid

client log

[2020-08-30T14:30:54Z INFO  substratee_stf::cli] getting pair for //AliceIncognito
[2020-08-30T14:30:54Z DEBUG substratee_stf::cli] attestations: [Attestation { claim: ClaimOfAttendance { claimant_public: 50503350955afe8a107d6f115dc253eb5d75a3fe37a90b373db26cc12e3c6661 (5Dt1Wg85...), ceremony_index: 37, currency_identifier: 0x62b697d59a41ecd5edfa0a9f8a26913ebe84d4f80edc1c934be7b6f9f633b05f, meetup_index: 1, location: Location { lat: 35.8935002615, lon: 25.9397506714 }, timestamp: 1598696174460, number_of_participants_confirmed: 3 }, signature: MultiSignature::Sr25519(ae939588504a73303007c6c05e380dd0127049e25292480103860df36899de0b222018174f099a4e531e6cd1a83964090d5fc631f162affd757b93b398a1428a), public: c24c5b3969d8ec4ca8a655a98dcc136d5d4c29d1206ffe7721e80ebdfa1d0b77 (5GTTq4En...) }, Attestation { claim: ClaimOfAttendance { claimant_public: 50503350955afe8a107d6f115dc253eb5d75a3fe37a90b373db26cc12e3c6661 (5Dt1Wg85...), ceremony_index: 37, currency_identifier: 0x62b697d59a41ecd5edfa0a9f8a26913ebe84d4f80edc1c934be7b6f9f633b05f, meetup_index: 1, location: Location { lat: 35.8935002615, lon: 25.9397506714 }, timestamp: 1598696174460, number_of_participants_confirmed: 3 }, signature: MultiSignature::Sr25519(c04957b36788363255074d6c38a7cee624e5d2fcb4e192731655c1c4d8784f2b55835adfb88de96d1a7f91a1b2c56fd8e1eede5d7054371b1a32f25a4a6ce987), public: a0f90738cda701bb8c8506bb278488e6efe8549489ef4cc77ca4024efb42311b (5FhmVhGB...) }]
send TrustedCall::register_attestations for 5Dt1Wg85pXGLstt36t6TDdvXXoCtG6zkUL17KkyVaPYSrzGH
[2020-08-30T14:30:54Z INFO  encointer_client_teeproxy] connecting to wss://cantillon.encointer.org:443
[2020-08-30T14:30:54Z INFO  encointer_client_teeproxy] Connecting to substraTEE-worker on 'wss://substratee03.scs.ch:443'
[2020-08-30T14:30:54Z INFO  substratee_worker_api] [Worker Api]: Sending request: PubKeyWorker
[2020-08-30T14:30:54Z DEBUG substratee_worker_api::client] sending request: PubKeyWorker
[2020-08-30T14:31:01Z INFO  substratee_worker_api::client] got message
[2020-08-30T14:31:01Z DEBUG substratee_worker_api::client] {"n":[67,31,237,44,246,132,149,105,205,31,148,202,175,33,75,60,58,92,166,37,249,236,153,80,56,5,128,1,104,115,185,58,87,35,4,183,111,29,38,18,57,125,104,139,199,241,30,132,115,98,56,52,177,216,54,228,206,111,48,205,192,163,39,114,119,154,214,203,48,185,171,211,224,25,27,212,50,106,210,101,225,182,169,128,64,199,11,171,131,117,46,131,149,101,104,26,173,138,68,202,77,99,22,167,192,23,141,171,250,201,122,36,111,1,72,154,67,164,183,66,63,170,42,215,104,81,193,65,195,180,121,22,199,191,77,210,47,219,186,207,175,82,248,112,2,96,162,203,77,224,201,87,80,188,147,191,74,143,175,147,18,123,158,60,152,76,202,247,103,88,16,121,81,115,192,244,121,129,28,97,132,136,142,186,180,8,9,4,240,2,140,83,60,129,124,102,26,200,21,19,199,215,251,96,109,109,198,102,32,26,18,45,57,108,240,114,186,193,158,137,125,23,156,212,235,192,107,133,104,247,161,43,132,224,180,135,52,12,109,68,199,39,201,185,252,103,212,103,193,131,194,70,50,103,54,109,6,8,97,235,241,167,247,252,142,151,83,17,123,1,234,17,205,201,153,159,113,145,224,145,63,227,19,35,252,249,177,2,34,48,126,76,4,237,175,97,176,32,250,212,8,27,110,246,71,172,15,250,151,195,145,165,98,84,6,130,222,85,194,6,148,152,110,203,215,236,137,86,132,129,157,62,98,9,118,129,122,71,101,144,66,72,4,91,226,114,161,56,208,182,1,12,196,194,68,187,73,111,34,240,15,190,133,178,175,63,9,41,194,10,167,1,84,153,128,183,145,119,147,240,196,96,102,144],"e":[1,0,0,1]}
[2020-08-30T14:31:01Z INFO  substratee_worker_api] [+] Got RSA public key of enclave
[2020-08-30T14:31:01Z DEBUG substratee_worker_api]   enclave RSA pubkey = Rsa3072KeyPair: { n:431FED2CF6849569CD1F94CAAF214B3C3A5CA625F9EC9950380580016873B93A572304B76F1D2612397D688BC7F11E8473623834B1D836E4CE6F30CDC0A32772779AD6CB30B9ABD3E0191BD4326AD265E1B6A98040C70BAB83752E839565681AAD8A44CA4D6316A7C0178DABFAC97A246F01489A43A4B7423FAA2AD76851C141C3B47916C7BF4DD22FDBBACFAF52F8700260A2CB4DE0C95750BC93BF4A8FAF93127B9E3C984CCAF7675810795173C0F479811C6184888EBAB4080904F0028C533C817C661AC81513C7D7FB606D6DC666201A122D396CF072BAC19E897D179CD4EBC06B8568F7A12B84E0B487340C6D44C727C9B9FC67D467C183C2463267366D060861EBF1A7F7FC8E9753117B01EA11CDC9999F7191E0913FE31323FCF9B10222307E4C04EDAF61B020FAD4081B6EF647AC0FFA97C391A562540682DE55C20694986ECBD7EC895684819D3E620976817A4765904248045BE272A138D0B6010CC4C244BB496F22F00FBE85B2AF3F0929C20AA701549980B7917793F0C4606690, e:01000001 }
[2020-08-30T14:31:01Z INFO  encointer_client_teeproxy] getting pair for //Alice
[2020-08-30T14:31:01Z INFO  encointer_client_teeproxy] Composing generic extrinsic for module "SubstrateeRegistry" and call "call_worker"
[2020-08-30T14:31:01Z INFO  encointer_client_teeproxy] stf call extrinsic sent. Hash: None
[2020-08-30T14:31:01Z INFO  encointer_client_teeproxy] waiting for confirmation of stf call
[2020-08-30T14:31:06Z ERROR substrate_api_client] couldn't decode event record list

worker log

2020-08-30T14:31:26Z DEBUG substratee_stf::sgx] CurrentPhase Some(Ok(ATTESTING))
[2020-08-30T14:31:26Z DEBUG substratee_stf::sgx] CurrentCeremonyIndex Some(Ok(37))
[2020-08-30T14:31:26Z DEBUG substratee_stf::sgx] Attestations [Attestation { claim: ClaimOfAttendance { claimant_public: , ceremony_index: 37, currency_identifier: 0x62b697d59a41ecd5edfa0a9f8a26913ebe84d4f80edc1c934be7b6f9f633b05f, meetup_index: 1, location: Location { lat: 35.8935002615, lon: 25.9397506714 }, timestamp: 1598696174460, number_of_participants_confirmed: 3 }, signature: <wasm:stripped>, public:  }, Attestation { claim: ClaimOfAttendance { claimant_public: , ceremony_index: 37, currency_identifier: 0x62b697d59a41ecd5edfa0a9f8a26913ebe84d4f80edc1c934be7b6f9f633b05f, meetup_index: 1, location: Location { lat: 35.8935002615, lon: 25.9397506714 }, timestamp: 1598696174460, number_of_participants_confirmed: 3 }, signature: <wasm:stripped>, public:  }]
[2020-08-30T14:31:26Z DEBUG sp_io::misc] ignoring claim beyond time tolerance (too early)
[2020-08-30T14:31:26Z DEBUG sp_io::misc] ignoring claim beyond time tolerance (too early)
[2020-08-30T14:31:26Z ERROR substratee_worker_enclave] Error performing Stf::execute. Error: Dispatch("ceremonies_register_attestations")
brenzi commented 4 years ago

tested again with v0.6.11 (upgraded pallets, fixing meetup time math)

[2020-08-30T17:44:20Z DEBUG substratee_stf::sgx] CurrentPhase Some(Ok(ATTESTING))
[2020-08-30T17:44:20Z DEBUG substratee_stf::sgx] CurrentCeremonyIndex Some(Ok(37))
[2020-08-30T17:44:20Z DEBUG substratee_stf::sgx] Attestations [Attestation { claim: ClaimOfAttendance { claimant_public: , ceremony_index: 37, currency_identifier: 0x62b697d59a41ecd5edfa0a9f8a26913ebe84d4f80edc1c934be7b6f9f633b05f, meetup_index: 1, location: Location { lat: 35.8935002615, lon: 25.9397506714 }, timestamp: 1598696174460, number_of_participants_confirmed: 3 }, signature: <wasm:stripped>, public:  }, Attestation { claim: ClaimOfAttendance { claimant_public: , ceremony_index: 37, currency_identifier: 0x62b697d59a41ecd5edfa0a9f8a26913ebe84d4f80edc1c934be7b6f9f633b05f, meetup_index: 1, location: Location { lat: 35.8935002615, lon: 25.9397506714 }, timestamp: 1598696174460, number_of_participants_confirmed: 3 }, signature: <wasm:stripped>, public:  }]
[2020-08-30T17:44:20Z DEBUG substratee_stf::sgx] NextPhaseTimestamp Some(Ok(1598832000000))
[2020-08-30T17:44:20Z DEBUG substratee_stf::sgx] PhaseDurations for ATTESTING None
[2020-08-30T17:44:20Z DEBUG sp_io::misc] ignoring claim beyond time tolerance (too early)
[2020-08-30T17:44:20Z DEBUG sp_io::misc] ignoring claim beyond time tolerance (too early)
[2020-08-30T17:44:20Z ERROR substratee_worker_enclave] Error performing Stf::execute. Error: Dispatch("ceremonies_register_attestations")

so the next_phase_timestamp is correct, however, the state for PhaseDurations hasn't been synched (its a map!)

brenzi commented 4 years ago

that was it!

[2020-08-30T17:52:23Z DEBUG substratee_stf::sgx] CurrentPhase Some(Ok(ATTESTING))                                                                                                  
[2020-08-30T17:52:23Z DEBUG substratee_stf::sgx] CurrentCeremonyIndex Some(Ok(37))
[2020-08-30T17:52:23Z DEBUG substratee_stf::sgx] Attestations [Attestation { claim: ClaimOfAttendance { claimant_public: , ceremony_index: 37, currency_identifier: 0x62b697d59a41ecd5edfa0a9f8a26913ebe84d4f80edc1c934be7b6f9f633b05f, meetup_index: 1, location: Location { lat: 35.8935002615, lon: 25.9397506714 }, timestamp: 1598696174460, number_of_participants_confirmed: 3 }, signature: <wasm:stripped>, public:  }, Attestation { claim: ClaimOfAttendance { claimant_public: , ceremony_index: 37, currency_identifier: 0x62b697d59a41ecd5edfa0a9f8a26913ebe84d4f80edc1c934be7b6f9f633b05f, meetup_index: 1, location: Location { lat: 35.8935002615, lon: 25.9397506714 }, timestamp: 1598696174460, number_of_participants_confirmed: 3 }, signature: <wasm:stripped>, public:  }]
[2020-08-30T17:52:23Z DEBUG substratee_stf::sgx] NextPhaseTimestamp Some(Ok(1598832000000))
[2020-08-30T17:52:23Z DEBUG substratee_stf::sgx] PhaseDurations for ATTESTING Some(Ok(172800000))
[2020-08-30T17:52:23Z DEBUG sp_io::misc] registered attestations for:
[2020-08-30T17:52:23Z DEBUG sp_io::misc] [80, 80, 51, 80, 149, 90, 254, 138, 16, 125, 111, 17, 93, 194, 83, 235, 93, 117, 163, 254, 55, 169, 11, 55, 61, 178, 108, 193, 46, 60, 102, 97]