search

maidsafe-archive / MaidSafe

This is the super-project in which each MaidSafe library resides. Some information is common to all libraries, and is detailed here. Library-specific information can be found in each library's wiki.
Other
583 stars 102 forks source link

Creating user and logging out occasionally fails on clean network #90

Closed ghost closed 11 years ago

ghost commented 11 years ago

As per https://basecamp.com/2074288/projects/1592290-lifestuff-dev/todos/23749552-23749552-determine

Ran test once on clean network and with clean lifestuff_mgr. I have had failures when creating an account then logging it out at the start of tests, and when CreateAndConnectTwoPublicIds is called in the setup of TwoUsersApiTests.

Example (TwoUsersApiTest):

[==========] Running 1 test from 1 test case.
[----------] Global test environment set-up.
[==========] 1 test from TwoUsersApiTest
[ RUN      ] TwoUsersApiTest.FUNC_AddContactWithMessage
I 1 15:37:54.908222 lifestuff/rcs_helper.cc:80] Started PD client node.
I 1 15:37:56.962812 lifestuff/detail/user_credentials_impl.cc:602] ANMID: 0, ANSMID: 0, ANTMID: 0, PMID path: 0
I 1 15:37:58.115641 lifestuff/detail/user_credentials_impl.cc:771] MID: 0, SMID: 0, TMID: 0, STMID: 0
I 1 15:38:03.131884 lifestuff/lifestuff_impl.cc:291] user_credentials_->CreateUser success.
I 1 15:38:03.751642 lifestuff/lifestuff_impl.cc:301] CreateVaultInLocalMachine success.
I 1 15:38:04.733174 lifestuff/lifestuff_impl.cc:310] SetValidPmidAndInitialisePublicComponents success.
I 3 15:38:39.698324 lifestuff/detail/public_id.cc:187] Stored ANMPID
I 3 15:39:04.032873 lifestuff/detail/public_id.cc:210] Stored MPID
I 3 15:39:04.123686 lifestuff/detail/public_id.cc:234] Stored MCID
I 3 15:39:14.494799 lifestuff/detail/public_id.cc:256] Stored MMID key
I 1 15:39:24.501225 lifestuff/detail/public_id.cc:154] result: 0
I 1 15:39:48.982018 lifestuff/detail/public_id.cc:1364] Success storing the lifestuff card.
I 1 15:39:48.982172 lifestuff/detail/public_id.cc:869] PublicId::GetNewContacts: EAtOK
I 4 15:39:54.070756 lifestuff/detail/public_id.cc:869] PublicId::GetNewContacts: EAtOK
I 5 15:39:59.070746 lifestuff/detail/public_id.cc:869] PublicId::GetNewContacts: EAtOK
S 1 15:39:59.071602 lifestuff/lifestuff_impl.cc:351] Success creating public ID: EAtOK
I 1 15:39:59.071690 lifestuff/tests/api/api_test_resources.cc:339] About to stop messages and intros
I 1 15:39:59.071798 lifestuff/tests/api/api_test_resources.cc:346] About to unmount drive
I 6 15:39:59.071807 lifestuff/detail/message_handler.cc:250] Timer cancel triggered: Operation canceled
I 1 15:39:59.112978 lifestuff/tests/api/api_test_resources.cc:353] About to log out
I 1 15:39:59.113083 lifestuff/detail/session.cc:401] SerialiseDataAtlas - Has drive data.
I 4 15:40:04.070746 lifestuff/detail/public_id.cc:855] Process has been stopped.
I 1 15:40:09.569769 lifestuff/detail/user_credentials_impl.cc:867] MID: 0, SMID: 0, TMID: 0, STMID: 0
S 1 15:40:09.569854 lifestuff/detail/user_credentials_impl.cc:883] Success in SaveSession.
I 1 15:40:09.680930 lifestuff/detail/routings_handler.cc:171] RoutingsHandler::DeleteRoutingObject erased: 1, out of: 1
I 1 15:40:09.713070 lifestuff/detail/routings_handler.cc:83] Cleared objects

I 1 15:40:09.741101 lifestuff/tests/api/api_test_resources.cc:385] 

Done with user 1

I 1 15:40:10.279744 lifestuff/rcs_helper.cc:80] Started PD client node.
I 1 15:40:12.730560 lifestuff/detail/user_credentials_impl.cc:602] ANMID: 0, ANSMID: 0, ANTMID: 0, PMID path: 0
I 1 15:40:13.962457 lifestuff/detail/user_credentials_impl.cc:771] MID: 0, SMID: 0, TMID: 0, STMID: 0
I 1 15:40:18.979474 lifestuff/lifestuff_impl.cc:291] user_credentials_->CreateUser success.
I 1 15:40:19.701094 lifestuff/lifestuff_impl.cc:301] CreateVaultInLocalMachine success.
I 1 15:40:30.857781 lifestuff/lifestuff_impl.cc:310] SetValidPmidAndInitialisePublicComponents success.
E 8 15:40:53.588503 lifestuff/detail/public_id.cc:183] ANMPID failed to store
I 1 15:40:53.588611 lifestuff/detail/public_id.cc:154] result: -200003
E 1 15:40:53.588677 lifestuff/detail/public_id.cc:157] Failed to store packets. result path: -200003
E 1 15:40:53.588731 lifestuff/detail/public_id.cc:111] Failed to store the packets to the network for OsOB0
E 1 15:40:53.588782 lifestuff/lifestuff_impl.cc:337] Failed to create public ID with result: -205008
I 1 15:40:53.588835 lifestuff/tests/api/api_test_resources.cc:339] About to stop messages and intros
I 1 15:40:53.588919 lifestuff/tests/api/api_test_resources.cc:346] About to unmount drive
I 1 15:40:53.626778 lifestuff/tests/api/api_test_resources.cc:353] About to log out
I 1 15:40:53.626884 lifestuff/detail/session.cc:401] SerialiseDataAtlas - Has drive data.
I 1 15:41:15.937831 lifestuff/detail/user_credentials_impl.cc:867] MID: -200003, SMID: 0, TMID: -200003, STMID: -200003
E 1 15:41:15.937894 lifestuff/detail/user_credentials_impl.cc:874] One of the operations for Identity Packets failed. Turn on INFO for feedback on which one. 
E 1 15:41:15.937956 lifestuff/detail/user_credentials_impl.cc:252] Failed to save session on Logout with result -207018
E 1 15:41:15.938013 lifestuff/lifestuff_impl.cc:432] Failed to log out with result -207018
E 1 15:41:15.938067 lifestuff/tests/api/api_test_resources.cc:356] Failed to create log out: -201009
E 1 15:41:15.938119 lifestuff/tests/api/api_test_resources.cc:422] Failure creating account
I 1 15:41:15.938176 lifestuff/detail/session.cc:401] SerialiseDataAtlas - Has drive data.
I 1 15:41:38.247820 lifestuff/detail/user_credentials_impl.cc:867] MID: -200003, SMID: 0, TMID: -200003, STMID: -200003
E 1 15:41:38.247883 lifestuff/detail/user_credentials_impl.cc:874] One of the operations for Identity Packets failed. Turn on INFO for feedback on which one. 
E 1 15:41:38.248033 lifestuff/detail/user_credentials_impl.cc:252] Failed to save session on Logout with result -207018
E 1 15:41:38.248120 lifestuff/lifestuff_impl.cc:432] Failed to log out with result -207018
W 1 15:41:38.248207 lifestuff/lifestuff_impl.cc:188] Should log out, but failed: -201009
W 1 15:41:38.248294 lifestuff/lifestuff_impl.cc:152] Quitting has failed in one of the clean up tasks: -201009
I 1 15:41:38.292879 lifestuff/detail/routings_handler.cc:83] Cleared objects

Segmentation fault (core dumped)

Example (OneUserApiTest):

[==========] Running 1 test from 1 test case.
[----------] Global test environment set-up.
[==========] 1 test from OneUserApiTest
[ RUN      ] OneUserApiTest.FUNC_LogInFromTwoPlaces
I 1 12:17:10.753769 lifestuff/tests/api/api_user_credentials_test.cc:706] 

ABOUT TO CREATE USER...

I 1 12:17:11.546837 lifestuff/rcs_helper.cc:80] Started PD client node.
I 1 12:17:13.999876 lifestuff/detail/user_credentials_impl.cc:602] ANMID: 0, ANSMID: 0, ANTMID: 0, PMID path: 0
I 1 12:17:15.035600 lifestuff/detail/user_credentials_impl.cc:771] MID: 0, SMID: 0, TMID: 0, STMID: 0
I 1 12:17:20.051455 lifestuff/lifestuff_impl.cc:291] user_credentials_->CreateUser success.
I 1 12:17:20.645142 lifestuff/lifestuff_impl.cc:301] CreateVaultInLocalMachine success.
I 1 12:17:31.332389 lifestuff/lifestuff_impl.cc:310] SetValidPmidAndInitialisePublicComponents success.
I 1 12:17:31.332477 lifestuff/tests/api/api_user_credentials_test.cc:711] 

CREATED USER. ABOUT TO LOG OUT...

I 1 12:17:53.696880 lifestuff/detail/user_credentials_impl.cc:867] MID: 0, SMID: 0, TMID: -200003, STMID: 0
E 1 12:17:53.696970 lifestuff/detail/user_credentials_impl.cc:874] One of the operations for Identity Packets failed. Turn on INFO for feedback on which one. 
E 1 12:17:53.697047 lifestuff/detail/user_credentials_impl.cc:252] Failed to save session on Logout with result -207018
E 1 12:17:53.697119 lifestuff/lifestuff_impl.cc:432] Failed to log out with result -207018
/home/alison/Development/Workspace/MaidSafe/src/lifestuff/src/maidsafe/lifestuff/tests/api/api_user_credentials_test.cc:712: Failure
Value of: test_elements.LogOut()
  Actual: -201009
Expected: kSuccess
Which is: 0
I 1 12:17:53.697284 lifestuff/tests/api/api_user_credentials_test.cc:713] 

LOGGED OUT.

I 1 12:18:16.107485 lifestuff/detail/user_credentials_impl.cc:867] MID: 0, SMID: -200003, TMID: 0, STMID: -200003
E 1 12:18:16.107636 lifestuff/detail/user_credentials_impl.cc:874] One of the operations for Identity Packets failed. Turn on INFO for feedback on which one. 
E 1 12:18:16.107710 lifestuff/detail/user_credentials_impl.cc:252] Failed to save session on Logout with result -207018
E 1 12:18:16.107767 lifestuff/lifestuff_impl.cc:432] Failed to log out with result -207018
W 1 12:18:16.107827 lifestuff/lifestuff_impl.cc:188] Should log out, but failed: -201009
W 1 12:18:16.107887 lifestuff/lifestuff_impl.cc:152] Quitting has failed in one of the clean up tasks: -201009
I 1 12:18:16.153534 lifestuff/detail/routings_handler.cc:83] Cleared objects

I killed this test after a few minutes of no output.

ghost commented 11 years ago

Here's another example of problems in the TwoUsersApiTest setup:

[==========] Running 1 test from 1 test case.
[----------] Global test environment set-up.
[==========] 1 test from TwoUsersApiTest
[ RUN      ] TwoUsersApiTest.FUNC_AddContactWithMessage
I 1 16:04:21.642676 lifestuff/rcs_helper.cc:80] Started PD client node.
I 1 16:04:23.656798 lifestuff/detail/user_credentials_impl.cc:602] ANMID: 0, ANSMID: 0, ANTMID: 0, PMID path: 0
I 1 16:04:24.650410 lifestuff/detail/user_credentials_impl.cc:771] MID: 0, SMID: 0, TMID: 0, STMID: 0
I 1 16:04:29.666611 lifestuff/lifestuff_impl.cc:291] user_credentials_->CreateUser success.
I 1 16:04:30.147887 lifestuff/lifestuff_impl.cc:301] CreateVaultInLocalMachine success.
I 1 16:04:31.038380 lifestuff/lifestuff_impl.cc:310] SetValidPmidAndInitialisePublicComponents success.
I 3 16:04:31.997368 lifestuff/detail/public_id.cc:187] Stored ANMPID
I 3 16:04:32.432460 lifestuff/detail/public_id.cc:210] Stored MPID
I 3 16:04:32.524151 lifestuff/detail/public_id.cc:234] Stored MCID
I 3 16:04:32.881790 lifestuff/detail/public_id.cc:256] Stored MMID key
I 1 16:04:33.002121 lifestuff/detail/public_id.cc:154] result: 0
I 1 16:04:33.520508 lifestuff/detail/public_id.cc:1364] Success storing the lifestuff card.
I 1 16:04:33.520681 lifestuff/detail/public_id.cc:869] PublicId::GetNewContacts: 0a6ZD
S 1 16:04:33.672664 lifestuff/lifestuff_impl.cc:351] Success creating public ID: 0a6ZD
I 1 16:04:33.672747 lifestuff/tests/api/api_test_resources.cc:339] About to stop messages and intros
I 1 16:04:33.672849 lifestuff/tests/api/api_test_resources.cc:346] About to unmount drive
I 4 16:04:33.672853 lifestuff/detail/public_id.cc:849] Timer cancel triggered: Operation canceled
I 4 16:04:33.673278 lifestuff/detail/message_handler.cc:250] Timer cancel triggered: Operation canceled
I 1 16:04:33.710789 lifestuff/tests/api/api_test_resources.cc:353] About to log out
I 1 16:04:33.710893 lifestuff/detail/session.cc:401] SerialiseDataAtlas - Has drive data.
I 1 16:04:34.532873 lifestuff/detail/user_credentials_impl.cc:867] MID: 0, SMID: 0, TMID: 0, STMID: 0
S 1 16:04:34.532966 lifestuff/detail/user_credentials_impl.cc:883] Success in SaveSession.
I 1 16:04:34.599274 lifestuff/detail/routings_handler.cc:171] RoutingsHandler::DeleteRoutingObject erased: 1, out of: 1
I 1 16:04:34.612651 lifestuff/detail/routings_handler.cc:83] Cleared objects

I 1 16:04:34.623110 lifestuff/tests/api/api_test_resources.cc:385] 

Done with user 1

I 1 16:04:35.219536 lifestuff/rcs_helper.cc:80] Started PD client node.
I 1 16:04:37.389683 lifestuff/detail/user_credentials_impl.cc:602] ANMID: 0, ANSMID: 0, ANTMID: 0, PMID path: 0
I 1 16:04:38.501931 lifestuff/detail/user_credentials_impl.cc:771] MID: 0, SMID: 0, TMID: 0, STMID: 0
I 1 16:04:43.515709 lifestuff/lifestuff_impl.cc:291] user_credentials_->CreateUser success.
I 1 16:04:44.288710 lifestuff/lifestuff_impl.cc:301] CreateVaultInLocalMachine success.
I 1 16:04:45.439578 lifestuff/lifestuff_impl.cc:310] SetValidPmidAndInitialisePublicComponents success.
I 6 16:04:46.423162 lifestuff/detail/public_id.cc:187] Stored ANMPID
I 7 16:05:10.846175 lifestuff/detail/public_id.cc:210] Stored MPID
I 7 16:05:10.940278 lifestuff/detail/public_id.cc:234] Stored MCID
I 7 16:05:35.573264 lifestuff/detail/public_id.cc:256] Stored MMID key
I 1 16:05:35.686764 lifestuff/detail/public_id.cc:154] result: 0
I 1 16:06:00.156025 lifestuff/detail/public_id.cc:1364] Success storing the lifestuff card.
I 1 16:06:00.156172 lifestuff/detail/public_id.cc:869] PublicId::GetNewContacts: trKEB
S 1 16:06:00.333673 lifestuff/lifestuff_impl.cc:351] Success creating public ID: trKEB
I 1 16:06:00.333758 lifestuff/tests/api/api_test_resources.cc:339] About to stop messages and intros
I 8 16:06:00.333854 lifestuff/detail/message_handler.cc:250] Timer cancel triggered: Operation canceled
I 1 16:06:00.333854 lifestuff/tests/api/api_test_resources.cc:346] About to unmount drive
I 9 16:06:00.333860 lifestuff/detail/public_id.cc:849] Timer cancel triggered: Operation canceled
I 1 16:06:00.370760 lifestuff/tests/api/api_test_resources.cc:353] About to log out
I 1 16:06:00.370865 lifestuff/detail/session.cc:401] SerialiseDataAtlas - Has drive data.
I 1 16:06:23.099212 lifestuff/detail/user_credentials_impl.cc:867] MID: 0, SMID: 0, TMID: 0, STMID: 0
S 1 16:06:23.099321 lifestuff/detail/user_credentials_impl.cc:883] Success in SaveSession.
I 1 16:06:23.173661 lifestuff/detail/routings_handler.cc:171] RoutingsHandler::DeleteRoutingObject erased: 1, out of: 1
I 1 16:06:23.187660 lifestuff/detail/routings_handler.cc:83] Cleared objects

I 1 16:06:23.198149 lifestuff/tests/api/api_test_resources.cc:394] 

Done with user 2

I 1 16:06:23.916347 lifestuff/rcs_helper.cc:80] Started PD client node.
I 1 16:06:24.328213 lifestuff/detail/user_credentials_impl.cc:322] mid_tmid_result: 0 - false - false
I 1 16:06:24.328275 lifestuff/detail/user_credentials_impl.cc:324] smid_stmid_result: 0 - false - false
I 1 16:06:24.328355 lifestuff/detail/session.cc:343] ParseDataAtlas - Has drive data.
I 1 16:06:29.594950 lifestuff/detail/routings_handler.cc:222] sender: 3162ff..3afcd1, receiver: 3162ff..3afcd1
I 10 16:06:29.606499 lifestuff/detail/routings_handler.cc:292] receiver: 3162ff..3afcd1, sender: 3162ff..3afcd1
I 10 16:06:29.612299 lifestuff/lifestuff_impl.cc:1307] It's our own message that has been received. Ignoring...
I 11 16:06:39.595112 lifestuff/detail/routings_handler.cc:210] Message count: 0
E 1 16:06:39.595223 lifestuff/detail/routings_handler.cc:241] Message from 3162ff..3afcd1 is empty. Probably timed out in routing.
W 1 16:06:39.595302 lifestuff/detail/user_credentials_impl.cc:195] Timed out. Not necessarily a failure.
I 1 16:06:40.480680 lifestuff/detail/public_id.cc:869] PublicId::GetNewContacts: 0a6ZD
I 1 16:06:40.792161 lifestuff/tests/api/api_test_resources.cc:339] About to stop messages and intros
I 1 16:06:40.792275 lifestuff/tests/api/api_test_resources.cc:346] About to unmount drive
I 10 16:06:40.792276 lifestuff/detail/public_id.cc:849] Timer cancel triggered: Operation canceled
I 13 16:06:40.792278 lifestuff/detail/message_handler.cc:250] Timer cancel triggered: Operation canceled
I 1 16:06:40.827023 lifestuff/tests/api/api_test_resources.cc:353] About to log out
I 1 16:06:40.827124 lifestuff/detail/session.cc:401] SerialiseDataAtlas - Has drive data.
I 1 16:06:40.827749 lifestuff/detail/session.cc:455] Added contact trKEB to 0a6ZD map.
I 1 16:06:51.285707 lifestuff/detail/user_credentials_impl.cc:867] MID: 0, SMID: 0, TMID: 0, STMID: 0
S 1 16:06:51.285801 lifestuff/detail/user_credentials_impl.cc:883] Success in SaveSession.
I 1 16:06:51.848986 lifestuff/detail/routings_handler.cc:171] RoutingsHandler::DeleteRoutingObject erased: 1, out of: 1
I 1 16:06:51.862112 lifestuff/detail/routings_handler.cc:83] Cleared objects

I 1 16:06:51.872599 lifestuff/tests/api/api_test_resources.cc:454] 

User 1 sent invitation to user 2

I 1 16:06:52.976494 lifestuff/rcs_helper.cc:80] Started PD client node.
E 14 16:07:14.977929 lifestuff/detail/user_credentials_impl.cc:373] No SMID found.
E 15 16:07:14.978278 lifestuff/detail/user_credentials_impl.cc:373] No MID found.
I 1 16:07:14.978384 lifestuff/detail/user_credentials_impl.cc:322] mid_tmid_result: -207008 - true - true
I 1 16:07:14.978476 lifestuff/detail/user_credentials_impl.cc:324] smid_stmid_result: -207008 - true - true
I 1 16:07:14.978548 lifestuff/detail/user_credentials_impl.cc:329] User doesn't exist: qUeE3B, 4916
I 1 16:07:14.978632 lifestuff/detail/user_credentials_impl.cc:143] UserCredentialsImpl::LogIn - failed to get user info.
E 1 16:07:14.978710 lifestuff/tests/api/api_test_resources.cc:319] Failed to create log in: -207002

I killed this test after several minutes of no output.