Concurrency issue

[sandreae]

I'm observing what I believe must be a concurrency bug of some kind.

The following code appears in a loop within a proptest test:

println!("Current documents len: {}", current_documents_len);
println!("Expected documents len: {}", expected_remaining_documents);
assert_eq!(
    current_documents_len, expected_remaining_documents,
    "Number of returned documents doesn't match expected remaining"
);

and the logging with assertion error is:

Current documents len: 2
Expected documents len: 2
thread 'proptests::tests::test_query' panicked at 'Test failed: assertion failed: `(left == right)`
  left: `1`,
 right: `2`: Number of returned documents doesn't match expected remaining;

It's quite a complex test, but still this logging seems rather strange. The observed bug happens on every run.

The full code is here: https://github.com/p2panda/aquadoggo/blob/a-strange-query-bug/aquadoggo/src/proptests/tests.rs

[Eh2406]

(I am not a maintainer of proptest.) That is a very weird error message. The link you provided appears to return a 404. It would be very impressive for it to be a concurrency bug, as Rust generally prevents those (or at least creates more ceremony around them). And concurrency bugs very rarely are 100% deterministic. Which suggests that it's either undefined behavior in some of your unsafe code, or a miss compilation in rustc.

[Eh2406]

By the way, here's an example of a rustc miss compilation that leads to back to back prints showing different things. I don't think it's actually relevant, but it is too fun an example not to share.

[sandreae]

Hi @Eh2406 and thanks for the comments. I see your point about the seemingly deterministic behaviour, it is definitely a new one for me in any case.

Apologies for the broken link, this one should be ok: https://github.com/p2panda/aquadoggo/blob/4385bda29e42ffdd790cf77d65f795be7f4a476e/aquadoggo/src/proptests/tests.rs#L168-L174

And you can see the logs in the ci here: https://github.com/p2panda/aquadoggo/actions/runs/4825533992/jobs/8596471145

Looking at it now, i see the earlier logs are printing in the correct order, so it seems it is a case of the prints being out of order rather than any concurrency issue.

[matthew-russo]

i think i see whats going on. There's an earlier failure that ends up being the final result that proptest prints.

thread 'proptests::tests::test_query' panicked at 'assertion failed: `(left == right)`
  left: `1`,
 right: `0`: Number of returned documents doesn't match expected remaining', aquadoggo/src/proptests/tests.rs:170:13
Current documents len: 1
Expected documents len: 1
Current documents len: 2
Expected documents len: 2
Current documents len: 1
Expected documents len: 0
thread 'proptests::tests::test_query' panicked at 'assertion failed: `(left == right)`
  left: `1`,
 right: `0`: Number of returned documents doesn't match expected remaining', aquadoggo/src/proptests/tests.rs:170:13
Current documents len: 2
Expected documents len: 2
Current documents len: 1
Expected documents len: 1
Current documents len: 2
Expected documents len: 2
thread 'proptests::tests::test_query' panicked at 'Test failed: assertion failed: `(left == right)`
  left: `1`,
 right: `0`: Number of returned documents doesn't match expected remaining; minimal failing input: (schema_ast, document_ast_collection) = (SchemaAST { name: SchemaName("test_schema"), description: SchemaDescription("My test schema"), id: Application(SchemaName("test_schema"), DocumentViewId([OperationId(Hash("0020d5d0aa939b5c8d5a08c53fc62c81cb299a9df2f9645fc9e383de3734d8f2a4a0"))])), fields: [SchemaField { name: FieldName("KurQwVS4Xg511Z0N4HBdA12Yn_dHxxX_ZP6hAqwE_T9_"), field_type: PinnedRelationList, relation_schema: Some(SchemaAST { name: SchemaName("test_schema"), description: SchemaDescription("My test schema"), id: Application(SchemaName("test_schema"), DocumentViewId([OperationId(Hash("00205086758ff3130bec79f5e21df561533a32f6fd89b7f6a133154a12b439c8d8c1"))])), fields: [SchemaField { name: FieldName("H_3sy"), field_type: Float, relation_schema: None }] }) }] }, [DocumentAST { schema_id: Application(SchemaName("test_schema"), DocumentViewId([OperationId(Hash("0020d5d0aa939b5c8d5a08c53fc62c81cb299a9df2f9645fc9e383de3734d8f2a4a0"))])), fields: [DocumentFieldValue { name: FieldName("KurQwVS4Xg511Z0N4HBdA12Yn_dHxxX_ZP6hAqwE_T9_"), value: PinnedRelationList([]) }] }, DocumentAST { schema_id: Application(SchemaName("test_schema"), DocumentViewId([OperationId(Hash("0020d5d0aa939b5c8d5a08c53fc62c81cb299a9df2f9645fc9e383de3734d8f2a4a0"))])), fields: [DocumentFieldValue { name: FieldName("KurQwVS4Xg511Z0N4HBdA12Yn_dHxxX_ZP6hAqwE_T9_"), value: PinnedRelationList([DocumentAST { schema_id: Application(SchemaName("test_schema"), DocumentViewId([OperationId(Hash("00205086758ff3130bec79f5e21df561533a32f6fd89b7f6a133154a12b439c8d8c1"))])), fields: [DocumentFieldValue { name: FieldName("H_3sy"), value: Float(15409248791.88115) }] }]) }] }])

you can see the first two failure messages are formatted slightly differently than the last.

 thread 'proptests::tests::test_query' panicked at 'assertion failed: `(left == right)`

this is a failure of a single case

 thread 'proptests::tests::test_query' panicked at 'Test failed: assertion failed: `(left == right)`

and this is the failure of the overall test, using the last failed result.

essentially

 Current documents len: 2
Expected documents len: 2
thread 'proptests::tests::test_query' panicked at 'Test failed: assertion failed: `(left == right)`

the first two lines of this are referring to a completely different execution than the last line

[sandreae]

Ah, thank you @matthew-russo! That makes sense and clearly this is not a concurrency bug :smile: