Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Flaky Test_CheckpointAfterMerge #6119

Closed
fasmat opened this issue Jul 10, 2024 · 1 comment
Closed

Flaky Test_CheckpointAfterMerge #6119

fasmat opened this issue Jul 10, 2024 · 1 comment
Labels
area/testing technical debt

Comments

@fasmat
Copy link
Member

fasmat commented Jul 10, 2024 •
edited
Loading

Description

Test failed in a PR with unrelated changes

Affected code

Test_CheckpointAfterMerge seems to be unstable a least on slower runners. Example CI run: https://github.com/spacemeshos/go-spacemesh/actions/runs/9873914275/job/27267233075 from PR #6115

=== Failed
=== FAIL: activation/e2e Test_CheckpointAfterMerge (10.88s)
    logger.go:146: 2024-07-10T12:21:01.408Z	INFO	initialized datastore	{"config": {"ATXSize":1000,"MalfeasanceSize":1000}}
    logger.go:146: 2024-07-10T12:21:01.417Z	INFO	grpc	starting grpc server	{"address": "127.0.0.1:0", "services": ["spacemesh.v1.PostService"]}
    logger.go:146: 2024-07-10T12:21:01.417Z	INFO	grpc	bound to address	{"address": "127.0.0.1:49269"}
    logger.go:146: 2024-07-10T12:21:01.418Z	DEBUG	creating post verifier
    logger.go:146: 2024-07-10T12:21:02.032Z	DEBUG	created post verifier
    logger.go:146: 2024-07-10T12:21:02.032Z	INFO	starting post verifier
    logger.go:146: 2024-07-10T12:21:02.032Z	INFO	scaling post verifier	{"current": 0, "new": 1}
    logger.go:146: 2024-07-10T12:21:02.032Z	INFO	started post verifier
    logger.go:146: 2024-07-10T12:21:02.033Z	INFO	worker-0	starting
    logger.go:146: 2024-07-10T12:21:02.202Z	INFO	preparing post initializer	{"opts": {"DataDir":"/var/folders/ng/t2lj_z6n4h30fn0h2ql_nd0c0000gn/T/Test_CheckpointAfterMerge877[682](https://github.com/spacemeshos/go-spacemesh/actions/runs/9873914275/job/27267233075#step:14:683)66/003","NumUnits":4,"MaxFileSize":4294967296,"ProviderID":{},"Throttle":false,"Scrypt":{"N":2,"R":1,"P":1},"ComputeBatchSize":1048576}}
    logger.go:146: 2024-07-10T12:21:02.203Z	INFO	waiting for ATXs to sync before selecting commitment ATX
    logger.go:146: 2024-07-10T12:21:02.203Z	INFO	ATXs synced - selecting commitment ATX
    logger.go:146: 2024-07-10T12:21:02.204Z	INFO	using golden atx as commitment atx
    logger.go:146: 2024-07-10T12:21:02.215Z	INFO	preparing post initializer	{"opts": {"DataDir":"/var/folders/ng/t2lj_z6n4h30fn0h2ql_nd0c0000gn/T/Test_CheckpointAfterMerge87768266/002","NumUnits":4,"MaxFileSize":4294967296,"ProviderID":{},"Throttle":false,"Scrypt":{"N":2,"R":1,"P":1},"ComputeBatchSize":1048576}}
    logger.go:146: 2024-07-10T12:21:02.217Z	INFO	waiting for ATXs to sync before selecting commitment ATX
    logger.go:146: 2024-07-10T12:21:02.217Z	INFO	ATXs synced - selecting commitment ATX
    logger.go:146: 2024-07-10T12:21:02.218Z	INFO	using golden atx as commitment atx
    logger.go:146: 2024-07-10T12:21:02.232Z	INFO	post setup session starting	{"node_id": "31d2a7c55ba1e29312ac71dd419b4edc019b6406960cfc8ffb3d7550dde2ca1b", "commitment_atx": "0203040000", "data_dir": "/var/folders/ng/t2lj_z6n4h30fn0h2ql_nd0c0000gn/T/Test_CheckpointAfterMerge87768266/003", "num_units": 4, "labels_per_unit": 64, "provider": "4294967295"}
    logger.go:146: 2024-07-10T12:21:02.233Z	INFO	initialization started	{"datadir": "/var/folders/ng/t2lj_z6n4h30fn0h2ql_nd0c0000gn/T/Test_CheckpointAfterMerge87768266/003", "numUnits": 4, "maxFileSize": 4294967296, "labelsPerUnit": 64}
    logger.go:146: 2024-07-10T12:21:02.233Z	INFO	initialization file layout	{"labelsPerFile": 2[684](https://github.com/spacemeshos/go-spacemesh/actions/runs/9873914275/job/27267233075#step:14:685)35456, "labelsLastFile": 256, "firstFileIndex": 0, "lastFileIndex": 0}
    logger.go:146: 2024-07-10T12:21:02.233Z	DEBUG	attempting to remove redundant files above index	{"maxFileIndex": 0}
    logger.go:146: 2024-07-10T12:21:02.234Z	INFO	initialization: starting to write file	{"fileIndex": 0, "currentNumLabels": 0, "targetNumLabels": 256, "startPosition": 0}
    logger.go:146: 2024-07-10T12:21:02.234Z	DEBUG	initialization: status	{"fileIndex": 0, "currentPosition": 0, "remaining": 256}
    logger.go:146: 2024-07-10T12:21:02.238Z	INFO	post setup session starting	{"node_id": "35a5d9365d1317c3002838126409e138321c57a5651d758485336c1e7e5af101", "commitment_atx": "0203040000", "data_dir": "/var/folders/ng/t2lj_z6n4h30fn0h2ql_nd0c0000gn/T/Test_CheckpointAfterMerge87768266/002", "num_units": 4, "labels_per_unit": 64, "provider": "4294967295"}
    logger.go:146: 2024-07-10T12:21:02.238Z	INFO	initialization started	{"datadir": "/var/folders/ng/t2lj_z6n4h30fn0h2ql_nd0c0000gn/T/Test_CheckpointAfterMerge87768266/002", "numUnits": 4, "maxFileSize": 4294967296, "labelsPerUnit": 64}
    logger.go:146: 2024-07-10T12:21:02.239Z	INFO	initialization file layout	{"labelsPerFile": 268435456, "labelsLastFile": 256, "firstFileIndex": 0, "lastFileIndex": 0}
    logger.go:146: 2024-07-10T12:21:02.239Z	DEBUG	attempting to remove redundant files above index	{"maxFileIndex": 0}
    logger.go:146: 2024-07-10T12:21:02.240Z	INFO	initialization: starting to write file	{"fileIndex": 0, "currentNumLabels": 0, "targetNumLabels": 256, "startPosition": 0}
    logger.go:146: 2024-07-10T12:21:02.240Z	DEBUG	initialization: status	{"fileIndex": 0, "currentPosition": 0, "remaining": 256}
    logger.go:146: 2024-07-10T12:21:02.264Z	DEBUG	Found new smallest nonce: Some(VrfNonce { index: 6, label: [5, 136, 101, 197, 242, 224, 112, 194, 23, 194, 80, 171, 16, 25, 162, 113, 205, 202, 174, 105, 226, 102, 32, 55, 194, 242, 58, 242, 154, 199, 0, 122] })	{"module": "post::initialize", "file": "src/initialize.rs", "line": 132}
    logger.go:146: 2024-07-10T12:21:02.264Z	DEBUG	Found new smallest nonce: Some(VrfNonce { index: 35, label: [5, 97, 179, 185, 89, 126, 175, 155, 157, 111, 8, 175, 3, 11, 215, 224, 76, 110, 66, 161, 57, 173, 73, 59, 59, 116, 42, 237, 168, 72, 0, 156] })	{"module": "post::initialize", "file": "src/initialize.rs", "line": 132}
    logger.go:146: 2024-07-10T12:21:02.264Z	DEBUG	Found new smallest nonce: Some(VrfNonce { index: 109, label: [0, 64, 157, 143, 60, 191, 101, 53, 35, 187, 25, 81, 54, 246, 103, 225, 83, 31, 93, 238, 192, 21, 186, 225, 137, 86, 119, 110, 188, 254, 149, 109] })	{"module": "post::initialize", "file": "src/initialize.rs", "line": 132}
    logger.go:146: 2024-07-10T12:21:02.264Z	DEBUG	Found new smallest nonce: Some(VrfNonce { index: 131, label: [0, 33, 151, 226, 159, 99, 191, 85, 187, 181, 167, 79, 170, 10, 219, 104, 24, 115, 208, 49, 9, 9, 3, 76, 72, 79, 83, 228, 73, 135, 253, 13] })	{"module": "post::initialize", "file": "src/initialize.rs", "line": 132}
    logger.go:146: 2024-07-10T12:21:02.265Z	DEBUG	initialization: found nonce	{"fileIndex": 0, "nonce": 131, "value": "002197e29f63bf55bbb5a74faa0adb68"}
    logger.go:146: 2024-07-10T12:21:02.266Z	INFO	initialization: found new best nonce	{"fileIndex": 0, "nonce": 131, "value": "002197e29f63bf55bbb5a74faa0adb68"}
    logger.go:146: 2024-07-10T12:21:02.312Z	DEBUG	Found new smallest nonce: Some(VrfNonce { index: 48, label: [0, 233, 101, 57, 135, 245, 94, 221, 214, 193, 94, 151, 137, 203, 154, 210, 123, 83, 204, 107, 62, 129, 187, 97, 59, 241, 62, 219, 96, 116, 92, 28] })	{"module": "post::initialize", "file": "src/initialize.rs", "line": 132}
    logger.go:146: 2024-07-10T12:21:02.313Z	DEBUG	initialization: found nonce	{"fileIndex": 0, "nonce": 48, "value": "00e9653987f55eddd6c15e9789cb9ad2"}
    logger.go:146: 2024-07-10T12:21:02.313Z	INFO	initialization: found new best nonce	{"fileIndex": 0, "nonce": 48, "value": "00e9653987f55eddd6c15e9789cb9ad2"}
    logger.go:146: 2024-07-10T12:21:02.329Z	INFO	initialization: completed	{"fileIndex": 0, "numLabelsWritten": 256}
    logger.go:146: 2024-07-10T12:21:02.333Z	INFO	initialization: completed, found nonce	{"nonce": 131}
    logger.go:146: 2024-07-10T12:21:02.333Z	INFO	post setup completed	{"node_id": "35a5d9365d1317c3002838126409e138321c57a5651d758485336c1e7e5af101", "commitment_atx": "0203040000", "data_dir": "/var/folders/ng/t2lj_z6n4h30fn0h2ql_nd0c0000gn/T/Test_CheckpointAfterMerge87768266/002", "num_units": 4, "labels_per_unit": 64, "provider": "4294967295"}
    logger.go:146: 2024-07-10T12:21:02.360Z	INFO	initialization: completed	{"fileIndex": 0, "numLabelsWritten": 256}
    logger.go:146: 2024-07-10T12:21:02.388Z	INFO	post service started	{"pid": 8076, "cmd": "/Users/runner/work/go-spacemesh/go-spacemesh/build/service --address http://127.0.0.1:49269 --min-num-units 1 --max-num-units 100 --k1 12 --k2 8 --pow-difficulty ffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffff --dir /var/folders/ng/t2lj_z6n4h30fn0h2ql_nd0c0000gn/T/Test_CheckpointAfterMerge87768266/002 -n 2 -r 1 -p 1 --threads 1 --nonces 16 --randomx-mode light --watch-pid 7725 --max-retries 10", "smesherID": "35a5d9"}
    logger.go:146: 2024-07-10T12:21:02.395Z	INFO	initialization: completed, found nonce	{"nonce": 48}
    logger.go:146: 2024-07-10T12:21:02.440Z	INFO	post setup completed	{"node_id": "31d2a7c55ba1e29312ac71dd419b4edc019b6406960cfc8ffb3d7550dde2ca1b", "commitment_atx": "0203040000", "data_dir": "/var/folders/ng/t2lj_z6n4h30fn0h2ql_nd0c0000gn/T/Test_CheckpointAfterMerge87768266/003", "num_units": 4, "labels_per_unit": 64, "provider": "4294967295"}
    logger.go:146: 2024-07-10T12:21:02.493Z	INFO	post service started	{"pid": 8077, "cmd": "/Users/runner/work/go-spacemesh/go-spacemesh/build/service --address http://127.0.0.1:49269 --min-num-units 1 --max-num-units 100 --k1 12 --k2 8 --pow-difficulty ffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffff --dir /var/folders/ng/t2lj_z6n4h30fn0h2ql_nd0c0000gn/T/Test_CheckpointAfterMerge87768266/003 -n 2 -r 1 -p 1 --threads 1 --nonces 16 --randomx-mode light --watch-pid 7725 --max-retries 10", "smesherID": "31d2a7"}
    logger.go:146: 2024-07-10T12:21:02.497Z	INFO	[2024-07-10T12:21:02Z INFO  service] POST network parameters: {"min_num_units":1,"max_num_units":100,"k1":12,"k2":8,"pow_difficulty":"FFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFF","scrypt":{"n":2,"r":1,"p":1}}	{"smesherID": "35a5d9"}
    logger.go:146: 2024-07-10T12:21:02.497Z	INFO	[2024-07-10T12:21:02Z INFO  service] POST proving settings: {"cores":{"threads":1,"pinned_cores":null},"nonces":16,"randomx_mode":"Light"}	{"smesherID": "35a5d9"}
    logger.go:146: 2024-07-10T12:21:02.498Z	INFO	[2024-07-10T12:21:02Z INFO  service] using 1 cores	{"smesherID": "35a5d9"}
    logger.go:146: 2024-07-10T12:21:02.498Z	INFO	[2024-07-10T12:21:02Z INFO  service] not configuring TLS	{"smesherID": "35a5d9"}
    logger.go:146: 2024-07-10T12:21:02.498Z	INFO	[2024-07-10T12:21:02Z INFO  service] watching PID 7725	{"smesherID": "35a5d9"}
    logger.go:146: 2024-07-10T12:21:02.504Z	INFO	[2024-07-10T12:21:02Z INFO  service] POST network parameters: {"min_num_units":1,"max_num_units":100,"k1":12,"k2":8,"pow_difficulty":"FFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFF","scrypt":{"n":2,"r":1,"p":1}}	{"smesherID": "31d2a7"}
    logger.go:146: 2024-07-10T12:21:02.504Z	INFO	[2024-07-10T12:21:02Z INFO  service] POST proving settings: {"cores":{"threads":1,"pinned_cores":null},"nonces":16,"randomx_mode":"Light"}	{"smesherID": "31d2a7"}
    logger.go:146: 2024-07-10T12:21:02.504Z	INFO	[2024-07-10T12:21:02Z INFO  service] using 1 cores	{"smesherID": "31d2a7"}
    logger.go:146: 2024-07-10T12:21:02.504Z	INFO	[2024-07-10T12:21:02Z INFO  service] not configuring TLS	{"smesherID": "31d2a7"}
    logger.go:146: 2024-07-10T12:21:02.504Z	INFO	[2024-07-10T12:21:02Z INFO  service] watching PID 7725	{"smesherID": "31d2a7"}
    logger.go:146: 2024-07-10T12:21:02.506Z	INFO	grpc	started streaming call	{"grpc.start_time": "2024-07-10T12:21:02Z", "system": "grpc", "span.kind": "server", "grpc.service": "spacemesh.v1.PostService", "grpc.method": "Register", "peer.address": "127.0.0.1:49271"}
    logger.go:146: 2024-07-10T12:21:02.508Z	INFO	post service registered	{"node_id": "31d2a7c55ba1e29312ac71dd419b4edc019b6406960cfc8ffb3d7550dde2ca1b"}
    logger.go:146: 2024-07-10T12:21:02.508Z	INFO	[2024-07-10T12:21:02Z INFO  post_service::client] obtained metadata: PostMetadata { node_id: [49, 210, 167, 197, 91, 161, 226, 147, 18, 172, 113, 221, 65, 155, 78, 220, 1, 155, 100, 6, 150, 12, 252, 143, 251, 61, 117, 80, 221, 226, 202, 27], commitment_atx_id: [2, 3, 4, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0], labels_per_unit: 64, num_units: 4, max_file_size: 4294967296, nonce: Some(48), last_position: None }	{"smesherID": "31d2a7"}
    logger.go:146: 2024-07-10T12:21:02.510Z	INFO	grpc	started streaming call	{"grpc.start_time": "2024-07-10T12:21:02Z", "system": "grpc", "span.kind": "server", "grpc.service": "spacemesh.v1.PostService", "grpc.method": "Register", "peer.address": "127.0.0.1:49270"}
    logger.go:146: 2024-07-10T12:21:02.511Z	INFO	[2024-07-10T12:21:02Z INFO  post_service::client] obtained metadata: PostMetadata { node_id: [53, 165, 217, 54, 93, 19, 23, 195, 0, 40, 56, 18, 100, 9, 225, 56, 50, 28, 87, 165, 101, 29, 117, 132, 133, 51, 108, 30, 126, 90, 241, 1], commitment_atx_id: [2, 3, 4, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0], labels_per_unit: 64, num_units: 4, max_file_size: 4294967296, nonce: Some(131), last_position: None }	{"smesherID": "35a5d9"}
    logger.go:146: 2024-07-10T12:21:02.512Z	INFO	post service registered	{"node_id": "35a5d9365d1317c3002838126409e138321c57a5651d758485336c1e7e5af101"}
    logger.go:146: 2024-07-10T12:21:02.604Z	INFO	atx handler created	{"supported ATX versions": ["vV1 from epoch 0", "vV2 from epoch 0"]}
    logger.go:146: 2024-07-10T12:21:02.605Z	INFO	nipostBuilder	post state changed	{"id": "31d2a7c55ba1e29312ac71dd419b4edc019b6406960cfc8ffb3d7550dde2ca1b", "state": "proving"}
    logger.go:146: 2024-07-10T12:21:02.605Z	INFO	nipostBuilder	post state changed	{"id": "35a5d9365d1317c3002838126409e138321c57a5651d758485336c1e7e5af101", "state": "proving"}
    logger.go:146: 2024-07-10T12:21:02.606Z	INFO	[2024-07-10T12:21:02Z INFO  post_service::service] starting proof generation for challenge 0000000000000000000000000000000000000000000000000000000000000000	{"smesherID": "35a5d9"}
    logger.go:146: 2024-07-10T12:21:02.606Z	INFO	[2024-07-10T12:21:02Z INFO  post_service::client] proof generation in progress	{"smesherID": "35a5d9"}
    logger.go:146: 2024-07-10T12:21:02.606Z	INFO	[2024-07-10T12:21:02Z INFO  post::prove] generating proof with PoW flags: RandomXFlag(FLAG_HARD_AES | FLAG_JIT | FLAG_ARGON2_SSSE3 | FLAG_ARGON2_AVX2), difficulty (scaled with SU): 864[691](https://github.com/spacemeshos/go-spacemesh/actions/runs/9873914275/job/27267233075#step:14:692)128455135232, K2PoW difficulty (scaled with SU): 3FFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFF	{"smesherID": "35a5d9"}
    logger.go:146: 2024-07-10T12:21:02.606Z	INFO	[2024-07-10T12:21:02Z INFO  post_service::service] starting proof generation for challenge 0000000000000000000000000000000000000000000000000000000000000000	{"smesherID": "31d2a7"}
    logger.go:146: 2024-07-10T12:21:02.607Z	INFO	[2024-07-10T12:21:02Z INFO  post_service::client] proof generation in progress	{"smesherID": "31d2a7"}
    logger.go:146: 2024-07-10T12:21:02.607Z	INFO	[2024-07-10T12:21:02Z INFO  post::prove] generating proof with PoW flags: RandomXFlag(FLAG_HARD_AES | FLAG_JIT | FLAG_ARGON2_SSSE3 | FLAG_ARGON2_AVX2), difficulty (scaled with SU): 864691128455135232, K2PoW difficulty (scaled with SU): 3FFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFF	{"smesherID": "31d2a7"}
    logger.go:146: 2024-07-10T12:21:04.628Z	INFO	[2024-07-10T12:21:04Z INFO  post_service::client] proof generation in progress	{"smesherID": "35a5d9"}
    logger.go:146: 2024-07-10T12:21:04.631Z	INFO	[2024-07-10T12:21:04Z INFO  post_service::client] proof generation in progress	{"smesherID": "31d2a7"}
    logger.go:146: 2024-07-10T12:21:06.655Z	INFO	[2024-07-10T12:21:06Z INFO  post_service::client] proof generation in progress	{"smesherID": "31d2a7"}
    logger.go:146: 2024-07-10T12:21:06.663Z	INFO	[2024-07-10T12:21:06Z INFO  post_service::client] proof generation in progress	{"smesherID": "35a5d9"}
    logger.go:146: 2024-07-10T12:21:08.666Z	INFO	[2024-07-10T12:21:08Z INFO  post_service::client] proof generation in progress	{"smesherID": "31d2a7"}
    logger.go:146: 2024-07-10T12:21:08.666Z	INFO	[2024-07-10T12:21:08Z INFO  post_service::client] proof generation in progress	{"smesherID": "35a5d9"}
    logger.go:146: 2024-07-10T12:21:09.116Z	INFO	[2024-07-10T12:21:09Z INFO  post::prove] calculating proof of work for nonces 0..16	{"smesherID": "31d2a7"}
    logger.go:146: 2024-07-10T12:21:09.268Z	INFO	[2024-07-10T12:21:09Z INFO  post::prove] calculating proof of work for nonces 0..16	{"smesherID": "35a5d9"}
    logger.go:146: 2024-07-10T12:21:09.273Z	INFO	[2024-07-10T12:21:09Z INFO  post::prove] finished k2pow in 0m 0s	{"smesherID": "31d2a7"}
    logger.go:146: 2024-07-10T12:21:09.309Z	INFO	[2024-07-10T12:21:09Z INFO  post::prove] started reading POST data	{"smesherID": "31d2a7"}
    logger.go:146: 2024-07-10T12:21:09.349Z	INFO	[2024-07-10T12:21:09Z INFO  post::reader] Reading file: /var/folders/ng/t2lj_z6n4h30fn0h2ql_nd0c0000gn/T/Test_CheckpointAfterMerge87768266/003/postdata_0.bin	{"smesherID": "31d2a7"}
    logger.go:146: 2024-07-10T12:21:09.349Z	INFO	[2024-07-10T12:21:09Z INFO  post::prove] finished reading POST data in 0m 0s	{"smesherID": "31d2a7"}
    logger.go:146: 2024-07-10T12:21:09.349Z	INFO	[2024-07-10T12:21:09Z INFO  post::prove] found proof for nonce: 2, pow: 0 with [8, 13, 15, 29, 45, 50, 59, 70] indices. It took 0m 0s	{"smesherID": "31d2a7"}
    logger.go:146: 2024-07-10T12:21:09.447Z	INFO	[2024-07-10T12:21:09Z INFO  post::prove] finished k2pow in 0m 0s	{"smesherID": "35a5d9"}
    logger.go:146: 2024-07-10T12:21:09.447Z	INFO	[2024-07-10T12:21:09Z INFO  post::prove] started reading POST data	{"smesherID": "35a5d9"}
    logger.go:146: 2024-07-10T12:21:09.452Z	INFO	[2024-07-10T12:21:09Z INFO  post::reader] Reading file: /var/folders/ng/t2lj_z6n4h30fn0h2ql_nd0c0000gn/T/Test_CheckpointAfterMerge87768266/002/postdata_0.bin	{"smesherID": "35a5d9"}
    logger.go:146: 2024-07-10T12:21:09.452Z	INFO	[2024-07-10T12:21:09Z INFO  post::prove] finished reading POST data in 0m 0s	{"smesherID": "35a5d9"}
    logger.go:146: 2024-07-10T12:21:09.452Z	INFO	[2024-07-10T12:21:09Z INFO  post::prove] found proof for nonce: 11, pow: 2 with [1, 17, 23, 28, 43, 54, 62, 75] indices. It took 0m 0s	{"smesherID": "35a5d9"}
    logger.go:146: 2024-07-10T12:21:10.667Z	INFO	[2024-07-10T12:21:10Z INFO  post_service::service] proof generation is finished	{"smesherID": "35a5d9"}
    logger.go:146: 2024-07-10T12:21:10.668Z	INFO	[2024-07-10T12:21:10Z INFO  post_service::client] proof generation finished	{"smesherID": "35a5d9"}
    logger.go:146: 2024-07-10T12:21:10.668Z	INFO	[2024-07-10T12:21:10Z INFO  post_service::client] verifying proof	{"smesherID": "35a5d9"}
    logger.go:146: 2024-07-10T12:21:10.668Z	INFO	[2024-07-10T12:21:10Z INFO  post_service::service] proof generation is finished	{"smesherID": "31d2a7"}
    logger.go:146: 2024-07-10T12:21:10.668Z	INFO	[2024-07-10T12:21:10Z INFO  post_service::client] proof generation finished	{"smesherID": "31d2a7"}
    logger.go:146: 2024-07-10T12:21:10.668Z	INFO	[2024-07-10T12:21:10Z INFO  post_service::client] verifying proof	{"smesherID": "31d2a7"}
    logger.go:146: 2024-07-10T12:21:11.225Z	INFO	nipostBuilder	post state changed	{"id": "31d2a7c55ba1e29312ac71dd419b4edc019b640[696](https://github.com/spacemeshos/go-spacemesh/actions/runs/9873914275/job/27267233075#step:14:697)0cfc8ffb3d7550dde2ca1b", "state": "idle"}
    logger.go:146: 2024-07-10T12:21:11.225Z	INFO	nipostBuilder	building nipost	{"smesherID": "31d2a7", "poet round start": "2024-07-10T12:21:08.000Z", "poet round end": "2024-07-10T12:21:09.250Z", "publish epoch end": "2024-07-10T12:21:13.000Z", "publish epoch": 1}
    logger.go:146: 2024-07-10T12:21:11.227Z	INFO	[2024-07-10T12:21:11Z INFO  post_service::client] proof is valid (verification took: 0.557015548s)	{"smesherID": "31d2a7"}
    logger.go:146: 2024-07-10T12:21:11.227Z	INFO	[2024-07-10T12:21:11Z INFO  post_service::client] proof is valid (verification took: 0.559936275s)	{"smesherID": "35a5d9"}
    logger.go:146: 2024-07-10T12:21:11.228Z	INFO	nipostBuilder	post state changed	{"id": "35a5d9365d1317c3002838126409e138321c57a5651d758485336c1e7e5af101", "state": "idle"}
    logger.go:146: 2024-07-10T12:21:11.228Z	INFO	nipostBuilder	building nipost	{"smesherID": "35a5d9", "poet round start": "2024-07-10T12:21:08.000Z", "poet round end": "2024-07-10T12:21:09.250Z", "publish epoch end": "2024-07-10T12:21:13.000Z", "publish epoch": 1}
    checkpoint_merged_test.go:158: 
        	Error Trace:	/Users/runner/work/go-spacemesh/go-spacemesh/activation/e2e/checkpoint_merged_test.go:158
        	Error:      	Received unexpected error:
        	            	builder: atx expired: poet round has already started at 2024-07-10 12:21:08 +0000 UTC (now: 2024-07-10 12:21:11.227228 +0000 UTC m=+118.750801938)
        	Test:       	Test_CheckpointAfterMerge
    logger.go:146: 2024-07-10T12:21:11.231Z	ERROR	grpc	finished streaming call with code Unknown	{"grpc.start_time": "2024-07-10T12:21:02Z", "system": "grpc", "span.kind": "server", "grpc.service": "spacemesh.v1.PostService", "grpc.method": "Register", "peer.address": "127.0.0.1:49270", "error": "context canceled", "grpc.code": "Unknown", "grpc.time_ms": 8720.211}
    logger.go:146: 2024-07-10T12:21:11.232Z	INFO	stopping post verifier
    logger.go:146: 2024-07-10T12:21:11.232Z	ERROR	grpc	finished streaming call with code Unknown	{"grpc.start_time": "2024-07-10T12:21:02Z", "system": "grpc", "span.kind": "server", "grpc.service": "spacemesh.v1.PostService", "grpc.method": "Register", "peer.address": "127.0.0.1:49271", "error": "context canceled", "grpc.code": "Unknown", "grpc.time_ms": 8725.765}
    logger.go:146: 2024-07-10T12:21:11.232Z	INFO	worker-0	stopped
    logger.go:146: 2024-07-10T12:21:11.253Z	INFO	stopped post verifier
    logger.go:146: 2024-07-10T12:21:11.254Z	INFO	grpc	stopping the grpc server
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
area/testing technical debt
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

[Merged by Bors] - stabilize e2e tests - take 2 spacemeshos/go-spacemesh
1 participant
@fasmat