at_libraries icon indicating copy to clipboard operation
at_libraries copied to clipboard

Functional test failing, but github job doesn't fail

Open gkc opened this issue 1 year ago • 7 comments

Describe the bug

When tests are failing in the test step of the functional_tests_at_onboarding_cli job defined in at_libraries.yaml, the overall job does not fail and so the test failures are not flagged on the PR

Steps to reproduce

See https://github.com/atsign-foundation/at_libraries/actions/runs/9191223708/job/25277175158 for example. Noticed in the course of working on https://github.com/atsign-foundation/at_libraries/pull/582

Expected behavior

If the tests fail then the job should fail

gkc avatar May 22 '24 12:05 gkc

@gkc were you able to get the tests to fail (in the same way locally)?

I'm trying to replicate, and it seems the tests are running OK against trunk.

cpswan avatar May 28 '24 17:05 cpswan

I fixed the tests last week. I'll make a branch for you and add a deliberately failing test

gkc avatar May 28 '24 17:05 gkc

@gkc I've gone back to #0805d1c which is where things were when that GitHub Actions job ran, and the tests pass locally for me, but there's no sign of any attempt to run enrollment_test.dart, which is where the failure happened.

Building package executable... (8.1s)
Built test:test.
00:06 +0: test/at_onboarding_cli_test.dart: A group of tests to assert on authenticate functionality A test to verify authentication is successful with .atKeys file
INFO|2024-05-29 11:11:53.647253|AtLookup|Creating new connection

INFO|2024-05-29 11:11:53.726525|AtLookup|New connection created OK

INFO|2024-05-29 11:11:53.739781|AtLookup|from result:data:_eb29f18a-1bc8-4dbf-910c-aff5c8912ce6@aliceđź› :34f3ac6a-67f2-4831-afd1-034075768893

INFO|2024-05-29 11:11:53.763665|AtLookup|auth success

INFO|2024-05-29 11:11:53.791702|OutboundConnectionImpl|close(): calling socket.destroy() on connection to InternetAddress('127.0.0.1', IPv4):25000

INFO|2024-05-29 11:11:53.874004|AtLookup|Creating new connection

INFO|2024-05-29 11:11:53.889748|AtLookup|New connection created OK

INFO|2024-05-29 11:11:53.972647|AtLookup|auth success

INFO|2024-05-29 11:11:53.974994|AtClientManager|setCurrentAtSign called with atSign @aliceđź› 

INFO|2024-05-29 11:11:53.975316|AtClientManager|Switching atSigns from null to @aliceđź› 

INFO|2024-05-29 11:11:54.004378|HiveBase|commit_log_0a406b4891f14d0fa7a716c9d4baf6c8abc3a84833452ad054a837c2b21cea6a initialized successfully

INFO|2024-05-29 11:11:54.014814|HiveBase|0a406b4891f14d0fa7a716c9d4baf6c8abc3a84833452ad054a837c2b21cea6a initialized successfully

INFO|2024-05-29 11:11:54.019494|AtClientCommitLogCompaction (@aliceđź› )|Starting commit log compaction job running for every 11 minute(s)

INFO|2024-05-29 11:11:54.088317|AtClientManager|setCurrentAtSign complete

00:07 +1: test/at_onboarding_cli_test.dart: A group of tests to assert on authenticate functionality A test to verify update and llookup verbs with authenticated atLookup instance
INFO|2024-05-29 11:11:54.175536|AtLookup|Creating new connection

INFO|2024-05-29 11:11:54.199409|AtLookup|New connection created OK

INFO|2024-05-29 11:11:54.270673|AtLookup|auth success

00:07 +1: test/at_onboarding_cli_test.dart: A group of tests to assert on authenticate functionality A test to verify authentication is successful with .atKeys file
INFO|2024-05-29 11:11:54.270919|AtClientManager|setCurrentAtSign called with atSign @aliceđź› 

INFO|2024-05-29 11:11:54.271067|AtClientManager|previous currentAtSign @aliceđź›  is same as new atSign @aliceđź›  - doing nothing, returning

INFO|2024-05-29 11:11:54.297531|AtLookup|Creating new connection

INFO|2024-05-29 11:11:54.321209|AtLookup|New connection created OK

INFO|2024-05-29 11:11:54.355656|AtLookup|auth success

00:07 +2: test/at_onboarding_cli_test.dart: A group of tests to assert on authenticate functionality A test to authenticate and atSign and invoke AtClient put and get methods
INFO|2024-05-29 11:11:54.381114|AtLookup|Creating new connection

INFO|2024-05-29 11:11:54.399061|AtLookup|New connection created OK

INFO|2024-05-29 11:11:54.409612|AtLookup|from result:data:_6eb1b6f8-6cb2-458e-966a-1a0923ee3386@eveđź› :f026b0c1-42f5-4f0f-845c-d7b477e1488a

INFO|2024-05-29 11:11:54.422706|AtLookup|auth success

INFO|2024-05-29 11:11:54.444686|OutboundConnectionImpl|close(): calling socket.destroy() on connection to InternetAddress('127.0.0.1', IPv4):25010

INFO|2024-05-29 11:11:54.456179|AtLookup|Creating new connection

INFO|2024-05-29 11:11:54.474913|AtLookup|New connection created OK

INFO|2024-05-29 11:11:54.513719|AtLookup|auth success

00:07 +2: test/at_onboarding_cli_test.dart: A group of tests to assert on authenticate functionality A test to verify authentication is successful with .atKeys file
INFO|2024-05-29 11:11:54.513978|AtClientManager|setCurrentAtSign called with atSign @eveđź› 

INFO|2024-05-29 11:11:54.514209|AtClientManager|Switching atSigns from @aliceđź›  to @eveđź› 

00:07 +2: test/at_onboarding_cli_test.dart: A group of tests to assert on authenticate functionality A test to authenticate and atSign and invoke AtClient put and get methods
INFO|2024-05-29 11:11:54.520957|HiveBase|commit_log_52c6e136524062d6def95e9fc56c27438ede6afb6245c5ea76f1c56ccd0778fc initialized successfully

INFO|2024-05-29 11:11:54.533887|HiveBase|52c6e136524062d6def95e9fc56c27438ede6afb6245c5ea76f1c56ccd0778fc initialized successfully

INFO|2024-05-29 11:11:54.534804|AtClientCommitLogCompaction (@eveđź› )|Starting commit log compaction job running for every 11 minute(s)

00:07 +2: test/at_onboarding_cli_test.dart: A group of tests to assert on authenticate functionality A test to verify authentication is successful with .atKeys file
INFO|2024-05-29 11:11:54.535608|AtClientCommitLogCompaction (@aliceđź› )|Stopping commit log compaction job

INFO|2024-05-29 11:11:54.540317|AtClientManager|setCurrentAtSign complete

00:07 +4: test/at_onboarding_cli_test.dart: A group of tests to assert encryption keys persist into local secondary A test to authenticate atSign and verify PKAM keys and encryption keys are updated to local secondary
INFO|2024-05-29 11:11:54.689817|AtLookup|Creating new connection

INFO|2024-05-29 11:11:54.717377|AtLookup|New connection created OK

INFO|2024-05-29 11:11:54.747690|AtLookup|auth success

00:07 +4: test/at_onboarding_cli_test.dart: A group of tests to assert on authenticate functionality A test to verify authentication is successful with .atKeys file
INFO|2024-05-29 11:11:54.748011|AtClientManager|setCurrentAtSign called with atSign @eveđź› 

INFO|2024-05-29 11:11:54.748142|AtClientManager|previous currentAtSign @eveđź›  is same as new atSign @eveđź›  - doing nothing, returning

00:11 +5: test/at_onboarding_cli_test.dart: ... verify atSign is onboarded and .atKeys file is generated successfully  Connecting to secondary ...1/50
00:11 +5: test/at_onboarding_cli_test.dart: A group of tests to verify onboard functionality A test to verify atSign is onboarded and .atKeys file is generated successfully
INFO|2024-05-29 11:11:58.839157|AtLookup|Creating new connection

INFO|2024-05-29 11:11:58.854587|AtLookup|New connection created OK

INFO|2024-05-29 11:11:58.866398|OutboundConnectionImpl|close(): calling socket.destroy() on connection to InternetAddress('127.0.0.1', IPv4):25006

INFO|2024-05-29 11:11:58.869358|AtLookup|Creating new connection

INFO|2024-05-29 11:11:58.884224|AtLookup|New connection created OK

INFO|2024-05-29 11:11:58.895588|AtLookup|from result:data:_bc22d7eb-814c-4671-b37f-6795f39d2470@egcovidlabđź› :bc6ef473-dd36-4c55-aaaf-15a7d9dd329a

INFO|2024-05-29 11:11:58.907519|AtLookup|auth success

INFO|2024-05-29 11:11:58.908312|AtAuthServiceImpl|Generating encryption keypair

INFO|2024-05-29 11:11:59.446104|AtAuthServiceImpl|[Information] Generating your encryption keys and .atKeys file


INFO|2024-05-29 11:11:59.446255|AtAuthServiceImpl|Generating pkam keypair

00:13 +5: test/at_onboarding_cli_test.dart: A group of tests to assert on authenticate functionality A test to authenticate and atSign and invoke AtClient put and get methods
INFO|2024-05-29 11:12:00.308501|AtLookup|Creating new connection

00:13 +5: test/at_onboarding_cli_test.dart: A group of tests to verify onboard functionality A test to verify atSign is onboarded and .atKeys file is generated successfully
INFO|2024-05-29 11:12:00.317151|OutboundConnectionImpl|close(): calling socket.destroy() on connection to InternetAddress('127.0.0.1', IPv4):25006

INFO|2024-05-29 11:12:00.317557|AtLookup|Creating new connection

INFO|2024-05-29 11:12:00.322555|AtLookup|New connection created OK

00:13 +5: test/at_onboarding_cli_test.dart: A group of tests to assert on authenticate functionality A test to authenticate and atSign and invoke AtClient put and get methods
INFO|2024-05-29 11:12:00.324594|AtLookup|New connection created OK

00:13 +5: test/at_onboarding_cli_test.dart: A group of tests to verify onboard functionality A test to verify atSign is onboarded and .atKeys file is generated successfully
INFO|2024-05-29 11:12:00.349569|AtLookup|auth success

00:13 +5: test/at_onboarding_cli_test.dart: A group of tests to assert on authenticate functionality A test to authenticate and atSign and invoke AtClient put and get methods
INFO|2024-05-29 11:12:00.355601|AtLookup|auth success

00:13 +5: test/at_onboarding_cli_test.dart: A group of tests to verify onboard functionality A test to verify atSign is onboarded and .atKeys file is generated successfully
INFO|2024-05-29 11:12:00.360774|AtAuthServiceImpl|Encryption public key update result data:2

00:13 +5: test/at_onboarding_cli_test.dart: A group of tests to assert on authenticate functionality A test to authenticate and atSign and invoke AtClient put and get methods
INFO|2024-05-29 11:12:00.366832|SyncService (@eveđź› )|148192220|Returning serverCommitId 2

00:13 +5: test/at_onboarding_cli_test.dart: A group of tests to verify onboard functionality A test to verify atSign is onboarded and .atKeys file is generated successfully
INFO|2024-05-29 11:12:00.377571|AtAuthServiceImpl|Cram secret delete response : data:-1

[Success] Your .atKeys file saved at /home/chris/.atsign/keys/@egcovidlabđź› _key.atKeys

00:13 +5: test/at_onboarding_cli_test.dart: A group of tests to assert on authenticate functionality A test to verify authentication is successful with .atKeys file
INFO|2024-05-29 11:12:00.387351|AtClientManager|setCurrentAtSign called with atSign @egcovidlabđź› 

INFO|2024-05-29 11:12:00.387541|AtClientManager|Switching atSigns from @eveđź›  to @egcovidlabđź› 

00:13 +5: test/at_onboarding_cli_test.dart: A group of tests to assert on authenticate functionality A test to authenticate and atSign and invoke AtClient put and get methods
INFO|2024-05-29 11:12:00.388470|SyncService (@eveđź› )|148192220|Returning serverCommitId 2

00:13 +5: test/at_onboarding_cli_test.dart: A group of tests to verify onboard functionality A test to verify atSign is onboarded and .atKeys file is generated successfully
INFO|2024-05-29 11:12:00.395961|HiveBase|commit_log_62d8a53cdc86e1329b338fc2868d51fc3a39bf99c3a89ccf7fd20b15e30ef9dc initialized successfully

INFO|2024-05-29 11:12:00.400047|HiveBase|62d8a53cdc86e1329b338fc2868d51fc3a39bf99c3a89ccf7fd20b15e30ef9dc initialized successfully

INFO|2024-05-29 11:12:00.400367|AtClientCommitLogCompaction (@egcovidlabđź› )|Starting commit log compaction job running for every 11 minute(s)

00:13 +5: test/at_onboarding_cli_test.dart: A group of tests to assert on authenticate functionality A test to authenticate and atSign and invoke AtClient put and get methods
INFO|2024-05-29 11:12:00.400695|AtClientCommitLogCompaction (@eveđź› )|Stopping commit log compaction job

00:13 +5: test/at_onboarding_cli_test.dart: A group of tests to assert on authenticate functionality A test to verify authentication is successful with .atKeys file
INFO|2024-05-29 11:12:00.401497|AtClientManager|setCurrentAtSign complete

00:13 +5: test/at_onboarding_cli_test.dart: A group of tests to assert on authenticate functionality A test to authenticate and atSign and invoke AtClient put and get methods
SEVERE|2024-05-29 11:12:00.446526|SyncService (@eveđź› )|Exception in sync f7b820b3-cb66-4a30-9813-5028131d4617. Reason: Failed to syncData caused by
local:lastreceivedservercommitid@eveđź›  is not a valid key

00:13 +5: test/at_onboarding_cli_test.dart: A group of tests to verify onboard functionality A test to verify atSign is onboarded and .atKeys file is generated successfully
INFO|2024-05-29 11:12:00.453845|AtLookup|Creating new connection

INFO|2024-05-29 11:12:00.469436|AtLookup|New connection created OK

INFO|2024-05-29 11:12:00.492617|OutboundConnectionImpl|close(): calling socket.destroy() on connection to InternetAddress('127.0.0.1', IPv4):25006

00:13 +6: test/at_onboarding_cli_test.dart: ... atSign is activated and .atKeys file is generated using activate_cli   [Information] Root server is vip.ve.atsign.zone
[Information] Registrar url provided is my.atsign.com
[Information] Activating your atSign. This may take up to 2 minutes.
00:17 +6: test/at_onboarding_cli_test.dart: ... atSign is activated and .atKeys file is generated using activate_cli   Connecting to secondary ...1/50
00:18 +6: test/at_onboarding_cli_test.dart: ... atSign is activated and .atKeys file is generated using activate_cli   [Success] Your .atKeys file saved at /home/chris/.atsign/keys/@muraliđź› _key.atKeys

cpswan avatar May 29 '24 10:05 cpswan

@gkc running these locally I get a 0 exit code despite tests failing

image

So this is a dart test thing rather than a GitHub Actions thing

cpswan avatar Jun 05 '24 12:06 cpswan

Carrying 2SP into PR89 as @gkc wants to do a little more testing before we open a ticket with the Dart team.

cpswan avatar Jun 10 '24 09:06 cpswan

@gkc I think we have an answer at https://github.com/dart-lang/test/issues/2248#issuecomment-2216278541

Looks like this is happening when we hit an exit(0) during a test.

We now have some head scratching to do in order to figure out correct behaviour under test versus in production (whilst the VM team do the same for the more general case of exit handling).

cpswan avatar Jul 09 '24 05:07 cpswan

Aha! Yes

gkc avatar Jul 10 '24 08:07 gkc

Evidence here that our test pack as whole will now, correctly, fail if there is any individual test failure.

gkc avatar Jul 18 '24 12:07 gkc