go run -tags online,logtrace cmd/main.go -session-id=+254722885991 [D] visedriver-config:config.go:102 conns conn=postgres://postgres:GHueXAX9Pury@10.0.0.2:5432/ge_ussd, user=postgres://postgres:GHueXAX9Pury@10.0.0.2:5432/ge_ussd [I] main:main.go:60 start command conn=map[0:conn: postgres://postgres:GHueXAX9Pury@10.0.0.2:5432/ge_ussd, mod TXT, typ POSTGRES 1:conn: /home/sohail/dev/sarafu-vise/services/registration, mod TXT, typ FS 2:conn: postgres://postgres:GHueXAX9Pury@10.0.0.2:5432/ge_ussd, mod BIN, typ POSTGRES], outputsize=160 [D] storage:storage_service.go:64 db check conn=conn: /home/sohail/dev/sarafu-vise/services/registration, mod TXT, typ FS, store=RESOURCE [I] storage:storage_service.go:120 connecting to db conn=conn: /home/sohail/dev/sarafu-vise/services/registration, mod TXT, typ FS, typ=1 [D] storage:storage_service.go:64 db check conn=conn: postgres://postgres:GHueXAX9Pury@10.0.0.2:5432/ge_ussd, mod TXT, typ POSTGRES, store=STATE [I] storage:storage_service.go:120 connecting to db conn=conn: postgres://postgres:GHueXAX9Pury@10.0.0.2:5432/ge_ussd, mod TXT, typ POSTGRES, typ=0 [D] storage:storage_service.go:172 missing session to apply store=&{0xc0003b4010 0xc000448000 public 0 true [] false} [T] storage:storage_service.go:190 menu storage service persist=persister @0xc00007f680 state:0x0 cache:0x0, store=&{0xc0003b4010 0xc000448000 public 0 true [] false} [D] storage:storage_service.go:64 db check conn=conn: postgres://postgres:GHueXAX9Pury@10.0.0.2:5432/ge_ussd, mod BIN, typ POSTGRES, store=USER [I] storage:storage_service.go:120 connecting to db conn=conn: postgres://postgres:GHueXAX9Pury@10.0.0.2:5432/ge_ussd, mod BIN, typ POSTGRES, typ=2 [D] storage:storage_service.go:172 missing session to apply store=&{0xc0003b4098 0xc000448240 public 0 true [] false} [D] gdbmdb:gdbm.go:90 gdbm connected connstr=db-logs/user-data [D] asm:flag.go:122 added flag translation from=flag_language_set, to=8, description=checks whether the user has set their prefered language [D] asm:flag.go:122 added flag translation from=flag_account_created, to=9, description=this is set when an account has been created on the API [D] asm:flag.go:122 added flag translation from=flag_account_creation_failed, to=10, description=this is set when there's an error from the API during account creation [D] asm:flag.go:122 added flag translation from=flag_account_pending, to=11, description=this is set when an account does not have a status of SUCCESS [D] asm:flag.go:122 added flag translation from=flag_account_success, to=12, description=this is set when an account has a status of SUCCESS [D] asm:flag.go:122 added flag translation from=flag_pin_mismatch, to=13, description=this is set when the confirmation PIN matches the initial PIN during registration [D] asm:flag.go:122 added flag translation from=flag_pin_set, to=14, description=this is set when a newly registered user sets a PIN. This must be present for an account to access the main menu [D] asm:flag.go:122 added flag translation from=flag_account_authorized, to=15, description=this is set to allow a user access guarded nodes after providing a correct PIN [D] asm:flag.go:122 added flag translation from=flag_invalid_recipient, to=16, description=this is set when the transaction recipient is invalid [D] asm:flag.go:122 added flag translation from=flag_invalid_recipient_with_invite, to=17, description=this is set when the transaction recipient is valid but not on the platform [D] asm:flag.go:122 added flag translation from=flag_invalid_amount, to=18, description=this is set when the given transaction amount is invalid [D] asm:flag.go:122 added flag translation from=flag_incorrect_pin, to=19, description=this is set when the provided PIN does not match the current account's PIN [D] asm:flag.go:122 added flag translation from=flag_valid_pin, to=20, description=this is set when the given PIN is valid [D] asm:flag.go:122 added flag translation from=flag_allow_update, to=21, description=this is set to allow a user to update their profile data [D] asm:flag.go:122 added flag translation from=flag_single_edit, to=22, description=this is set to allow a user to edit a single profile item such as year of birth [D] asm:flag.go:122 added flag translation from=flag_incorrect_date_format, to=23, description=this is set when the given year of birth is invalid [D] asm:flag.go:122 added flag translation from=flag_incorrect_voucher, to=24, description=this is set when the selected voucher is invalid [D] asm:flag.go:122 added flag translation from=flag_api_call_error, to=25, description=this is set when communication to an external service fails [D] asm:flag.go:122 added flag translation from=flag_no_active_voucher, to=26, description=this is set when a user does not have an active voucher [D] asm:flag.go:122 added flag translation from=flag_admin_privilege, to=27, description=this is set when a user has admin privileges. [D] asm:flag.go:122 added flag translation from=flag_unregistered_number, to=28, description=this is set when an unregistered phonenumber tries to perform an action [D] asm:flag.go:122 added flag translation from=flag_no_transfers, to=29, description=this is set when a user does not have any transactions [D] asm:flag.go:122 added flag translation from=flag_incorrect_statement, to=30, description=this is set when the selected statement is invalid [D] asm:flag.go:122 added flag translation from=flag_firstname_set, to=31, description=this is set when the first name of the profile is set [D] asm:flag.go:122 added flag translation from=flag_familyname_set, to=32, description=this is set when the family name of the profile is set [D] asm:flag.go:122 added flag translation from=flag_yob_set, to=33, description=this is set when the yob of the profile is set [D] asm:flag.go:122 added flag translation from=flag_gender_set, to=34, description=this is set when the gender of the profile is set [D] asm:flag.go:122 added flag translation from=flag_location_set, to=35, description=this is set when the location of the profile is set [D] asm:flag.go:122 added flag translation from=flag_offerings_set, to=36, description=this is set when the offerings of the profile is set [D] asm:flag.go:122 added flag translation from=flag_back_set, to=37, description=this is set when it is a back navigation [D] asm:flag.go:122 added flag translation from=flag_account_blocked, to=38, description=this is set when an account has been blocked after the allowed incorrect PIN attempts have been exceeded [D] asm:flag.go:122 added flag translation from=flag_invalid_pin, to=39, description=this is set when the given PIN is invalid(is less than or more than 4 digits) [D] asm:flag.go:122 added flag translation from=flag_alias_set, to=40, description=this is set when an account alias has been assigned to a user [D] asm:flag.go:122 added flag translation from=flag_account_pin_reset, to=41, description=this is set on an account when an admin triggers a PIN reset for themflag [D] asm:flag.go:122 added flag translation from=flag_incorrect_pool, to=42, description=this is set when the user selects an invalid pool [D] asm:flag.go:122 added flag translation from=flag_low_swap_amount, to=43, description=this is set when the swap max limit is less than 0.1 [D] asm:flag.go:122 added flag translation from=flag_alias_unavailable, to=44, description=this is set when the preferred alias is not available [D] engine:db.go:204 defer persist state set until state set in engine [D] engine:db.go:221 defer persist memory set until memory set in engine [D] engine:db.go:161 new engine state added state=state @0xc0003b0200 moves: 0 idx: 0 flags: 0x0000000000000000000000000000000000 path: lang: (default) [D] engine:db.go:183 new engine memory added memory=&{0 0 [map[]] map[] false} [D] engine:db.go:235 using engine state for persister state=state @0xc0003b0200 moves: 0 idx: 0 flags: 0x0000000000000000000000000000000000 path: lang: (default) [D] engine:db.go:246 using engine memory for persister memory=&{0 0 [map[]] map[] false} [T] db:db.go:280 made db lookup key lk=102b323534373232383835393931, pfx=16 [T] postgresdb:pg.go:98 begin single tx err= [T] postgresdb:pg.go:181 get key=2b323534373232383835393931 [T] postgresdb:pg.go:118 stop single tx err= [I] persist:persist.go:126 loaded state and cache self=persister @0xc00007f680 state:0xc0003b0200 cache:0xc000438540, key=+254722885991, state=state @0xc0003b0200 moves: 1350 idx: 0 flags: 0x065320801f000000000000000000000000 path: lang: eng (English) [T] persist:persist.go:127 loaded bytecode code=00080473656e64013100080c737761705f746f5f6c697374013200080b6d795f766f756368657273013300080b73656c6563745f706f6f6c013400080a6d795f6163636f756e74013500080468656c7001360008047175697401390008012e012a [T] engine:db.go:264 set persister st=state @0xc0003b0200 moves: 1350 idx: 0 flags: 0x065320801f000000000000000000000000 path: lang: eng (English), cac=&{0 20 [map[check_account_status: check_balance:Balance: 34.95 cUSD check_vouchers: manage_vouchers: validate_recipient:]] map[authorize_account:6 check_account_created:2 check_account_status:0 check_balance:128 check_blocked_status:1 check_identifier:0 check_pin_mismatch:6 check_transactions:0 check_vouchers:10 clear_temporary_value:2 confirm_new_alias:0 confirm_pin_change:0 create_account:0 fetch_community_balance:0 get_amount:32 get_current_profile_info:0 get_default_pool:20 get_pools:0 get_profile_info:0 get_recipient:0 get_sender:64 get_suggested_alias:0 get_transactions:0 get_voucher_details:0 get_vouchers:0 initiate_swap:0 initiate_transaction:0 invite_valid_recipient:0 manage_vouchers:160 max_amount:40 quit:0 quit_with_help:0 request_custom_alias:0 reset_account_authorized:16 reset_allow_update:0 reset_api_call_failure:6 reset_incorrect:6 reset_incorrect_date_format:8 reset_incorrect_pin:6 reset_invalid_pin:6 reset_others_pin:6 reset_transaction_amount:0 reset_unregistered_number:0 retrieve_blocked_number:0 save_familyname:64 save_firstname:128 save_gender:32 save_location:16 save_offerings:8 save_others_temporary_pin:6 save_temporary_pin:1 save_yob:32 set_back:6 set_default_voucher:8 set_language:6 set_pool:20 set_voucher:12 show_blocked_account:0 swap_max_limit:64 swap_preview:0 swap_to_list:0 transaction_reset:0 update_all_profile_items:0 validate_amount:64 validate_blocked_number:6 validate_recipient:50 verify_create_pin:8 verify_new_pin:2 verify_yob:6 view_pool:80 view_statement:0 view_voucher:80] false}, session=+254722885991, persister=persister @0xc00007f680 state:0xc0003b0200 cache:0xc000438540 [I] vm:runner.go:63 vm created with state state=state @0xc0003b0200 moves: 1350 idx: 0 flags: 0x065320801f000000000000000000000000 path: lang: eng (English), renderer= [T] engine:db.go:422 set language on context lang=eng (English) [D] engine:db.go:329 start pre-VM check [I] vm:runner.go:63 vm created with state state=state @0xc0003b0200 moves: 1351 idx: 0 flags: 0x065320801f000000000000000000000000 path: _first lang: eng (English), renderer= [T] vm:runner.go:120 new vm run [D] vm:runner.go:152 execute code opcode=3, op=LOAD, code=065f666972737401000007 [D] vm:runner.go:153 state=state @0xc0003b0200 moves: 1351 idx: 0 flags: 0x105320801f000000000000000000000000 path: _first lang: eng (English) [D] ussdmenuhandler:menuhandler.go:138 handler has been initialized state=state @0xc0003b0200 moves: 1351 idx: 0 flags: 0x105320801f000000000000000000000000 path: _first lang: eng (English), cache=&{0 20 [map[check_account_status: check_balance:Balance: 34.95 cUSD check_vouchers: manage_vouchers: validate_recipient:] map[]] map[authorize_account:6 check_account_created:2 check_account_status:0 check_balance:128 check_blocked_status:1 check_identifier:0 check_pin_mismatch:6 check_transactions:0 check_vouchers:10 clear_temporary_value:2 confirm_new_alias:0 confirm_pin_change:0 create_account:0 fetch_community_balance:0 get_amount:32 get_current_profile_info:0 get_default_pool:20 get_pools:0 get_profile_info:0 get_recipient:0 get_sender:64 get_suggested_alias:0 get_transactions:0 get_voucher_details:0 get_vouchers:0 initiate_swap:0 initiate_transaction:0 invite_valid_recipient:0 manage_vouchers:160 max_amount:40 quit:0 quit_with_help:0 request_custom_alias:0 reset_account_authorized:16 reset_allow_update:0 reset_api_call_failure:6 reset_incorrect:6 reset_incorrect_date_format:8 reset_incorrect_pin:6 reset_invalid_pin:6 reset_others_pin:6 reset_transaction_amount:0 reset_unregistered_number:0 retrieve_blocked_number:0 save_familyname:64 save_firstname:128 save_gender:32 save_location:16 save_offerings:8 save_others_temporary_pin:6 save_temporary_pin:1 save_yob:32 set_back:6 set_default_voucher:8 set_language:6 set_pool:20 set_voucher:12 show_blocked_account:0 swap_max_limit:64 swap_preview:0 swap_to_list:0 transaction_reset:0 update_all_profile_items:0 validate_amount:64 validate_blocked_number:6 validate_recipient:50 verify_create_pin:8 verify_new_pin:2 verify_yob:6 view_pool:80 view_statement:0 view_voucher:80] false}, x-SessionId=+254722885991 [D] cache:cache.go:70 Cache add key=_first, size=0, limit=0 [T] cache:cache.go:71 Cache add data value= [D] vm:runner.go:152 execute code opcode=7, op=HALT, code= [D] vm:runner.go:153 state=state @0xc0003b0200 moves: 1351 idx: 0 flags: 0x105320801f000000000000000000000000 path: _first lang: eng (English) [D] vm:runner.go:440 found HALT, stopping [D] engine:db.go:361 end pre-VM check [T] state:state.go:319 execpath before path=[_first] [T] state:state.go:326 execpath after path=[] [D] cache:cache.go:171 Cache free frame=1, key=_first, size=0 [T] engine:db.go:602 reset on pristine state is a noop [I] engine:db.go:521 new VM execution with input input= [D] engine:db.go:530 start VM run code=00080473656e64013100080c737761705f746f5f6c697374013200080b6d795f766f756368657273013300080b73656c6563745f706f6f6c013400080a6d795f6163636f756e74013500080468656c7001360008047175697401390008012e012a [T] vm:runner.go:120 new vm run [D] vm:runner.go:152 execute code opcode=8, op=INCMP, code=0473656e64013100080c737761705f746f5f6c697374013200080b6d795f766f756368657273013300080b73656c6563745f706f6f6c013400080a6d795f6163636f756e74013500080468656c7001360008047175697401390008012e012a [D] vm:runner.go:153 state=state @0xc0003b0200 moves: 1352 idx: 0 flags: 0x105320801f000000000000000000000000 path: lang: eng (English) [T] vm:runner.go:396 testing sym sym=send, input= [D] vm:runner.go:152 execute code opcode=8, op=INCMP, code=0c737761705f746f5f6c697374013200080b6d795f766f756368657273013300080b73656c6563745f706f6f6c013400080a6d795f6163636f756e74013500080468656c7001360008047175697401390008012e012a [D] vm:runner.go:153 state=state @0xc0003b0200 moves: 1352 idx: 0 flags: 0x115320801f000000000000000000000000 path: lang: eng (English) [T] vm:runner.go:396 testing sym sym=swap_to_list, input= [D] vm:runner.go:152 execute code opcode=8, op=INCMP, code=0b6d795f766f756368657273013300080b73656c6563745f706f6f6c013400080a6d795f6163636f756e74013500080468656c7001360008047175697401390008012e012a [D] vm:runner.go:153 state=state @0xc0003b0200 moves: 1352 idx: 0 flags: 0x115320801f000000000000000000000000 path: lang: eng (English) [T] vm:runner.go:396 testing sym sym=my_vouchers, input= [D] vm:runner.go:152 execute code opcode=8, op=INCMP, code=0b73656c6563745f706f6f6c013400080a6d795f6163636f756e74013500080468656c7001360008047175697401390008012e012a [D] vm:runner.go:153 state=state @0xc0003b0200 moves: 1352 idx: 0 flags: 0x115320801f000000000000000000000000 path: lang: eng (English) [T] vm:runner.go:396 testing sym sym=select_pool, input= [D] vm:runner.go:152 execute code opcode=8, op=INCMP, code=0a6d795f6163636f756e74013500080468656c7001360008047175697401390008012e012a [D] vm:runner.go:153 state=state @0xc0003b0200 moves: 1352 idx: 0 flags: 0x115320801f000000000000000000000000 path: lang: eng (English) [T] vm:runner.go:396 testing sym sym=my_account, input= [D] vm:runner.go:152 execute code opcode=8, op=INCMP, code=0468656c7001360008047175697401390008012e012a [D] vm:runner.go:153 state=state @0xc0003b0200 moves: 1352 idx: 0 flags: 0x115320801f000000000000000000000000 path: lang: eng (English) [T] vm:runner.go:396 testing sym sym=help, input= [D] vm:runner.go:152 execute code opcode=8, op=INCMP, code=047175697401390008012e012a [D] vm:runner.go:153 state=state @0xc0003b0200 moves: 1352 idx: 0 flags: 0x115320801f000000000000000000000000 path: lang: eng (English) [T] vm:runner.go:396 testing sym sym=quit, input= [D] vm:runner.go:152 execute code opcode=8, op=INCMP, code=012e012a [D] vm:runner.go:153 state=state @0xc0003b0200 moves: 1352 idx: 0 flags: 0x115320801f000000000000000000000000 path: lang: eng (English) [T] vm:runner.go:396 testing sym sym=., input= [D] vm:runner.go:399 input wildcard match input=, next=. [T] resource:db.go:117 getcode sym= [T] db:db.go:280 made db lookup key lk=01, pfx=1 [T] fsdb:fs.go:113 fs get skip missing i=0 [T] fsdb:fs.go:113 fs get skip missing i=1 [T] fsdb:fs.go:116 trying fs get i=2, key=, path=/home/sohail/dev/sarafu-vise/services/registration/1 [T] fsdb:fs.go:116 trying fs get i=3, key=, path=/home/sohail/dev/sarafu-vise/services/registration/.bin [E] engine:db.go:533 fail VM run with state code=, state=state @0xc0003b0200 moves: 1353 idx: 0 flags: 0x125320801f000000000000000000000000 path: lang: eng (English), vm=vm (0xc0004f4f00) ok [I] persist:persist.go:100 saving state and cache self=persister @0xc00007f680 state:0xc0003b0200 cache:0xc000438540, key=+254722885991, state=state @0xc0003b0200 moves: 1353 idx: 0 flags: 0x125320801f000000000000000000000000 path: lang: eng (English) [T] persist:persist.go:101 saving bytecode code= [T] db:db.go:280 made db lookup key lk=102b323534373232383835393931, pfx=16 [T] postgresdb:pg.go:98 begin single tx err= [T] postgresdb:pg.go:154 put key=2b323534373232383835393931, val=a2655374617465a764436f646540684578656350617468806742697453697a6518886753697a654964780065466c61677351125320801f000000000000000000000000654d6f766573190549684c616e6775616765a264436f646563656e67644e616d6567456e676c697368664d656d6f7279a569436163686553697a65006c436163686555736553697a651465436163686581a56e636865636b5f766f756368657273607276616c69646174655f726563697069656e74606f6d616e6167655f766f756368657273606d636865636b5f62616c616e63657442616c616e63653a2033342e393520635553440a74636865636b5f6163636f756e745f737461747573606553697a6573b84874726571756573745f637573746f6d5f616c6961730072636865636b5f7472616e73616374696f6e73006e766965775f73746174656d656e74006d696e6974696174655f73776170006e737761705f6d61785f6c696d697418407819736176655f6f74686572735f74656d706f726172795f70696e0671617574686f72697a655f6163636f756e7406717665726966795f6372656174655f70696e086f6d616e6167655f766f75636865727318a075636865636b5f6163636f756e745f637265617465640272636f6e6669726d5f70696e5f6368616e6765007372657365745f696e636f72726563745f70696e066a6765745f73656e64657218406c6765745f766f75636865727300736765745f766f75636865725f64657461696c7300717472616e73616374696f6e5f726573657400781972657365745f756e726567697374657265645f6e756d626572006f76616c69646174655f616d6f756e7418406f72657365745f696e636f7272656374067776616c69646174655f626c6f636b65645f6e756d6265720678186765745f63757272656e745f70726f66696c655f696e666f007276616c69646174655f726563697069656e741832706765745f64656661756c745f706f6f6c1474636865636b5f6163636f756e745f737461747573007772657472696576655f626c6f636b65645f6e756d626572006c737761705f746f5f6c697374006e7665726966795f6e65775f70696e026e736176655f6f66666572696e677308781872657365745f7472616e73616374696f6e5f616d6f756e74006b736176655f67656e64657218206e6372656174655f6163636f756e7400781b72657365745f696e636f72726563745f646174655f666f726d6174086e636865636b5f766f7563686572730a687365745f706f6f6c1478187570646174655f616c6c5f70726f66696c655f6974656d73007272657365745f616c6c6f775f7570646174650068736176655f796f6218206c737761705f707265766965770072736176655f74656d706f726172795f70696e0169766965775f706f6f6c1850736765745f7375676765737465645f616c696173006f736176655f66616d696c796e616d651840781872657365745f6163636f756e745f617574686f72697a6564106d6765745f726563697069656e74007672657365745f6170695f63616c6c5f6661696c757265066e736176655f66697273746e616d651880737365745f64656661756c745f766f75636865720875636c6561725f74656d706f726172795f76616c75650274636865636b5f626c6f636b65645f7374617475730170636865636b5f6964656e746966696572006c7365745f6c616e6775616765067172657365745f696e76616c69645f70696e066471756974007473686f775f626c6f636b65645f6163636f756e74006a6d61785f616d6f756e741828687365745f6261636b067072657365745f6f74686572735f70696e066a6765745f616d6f756e7418206d636865636b5f62616c616e636518806d736176655f6c6f636174696f6e106c766965775f766f7563686572185076696e766974655f76616c69645f726563697069656e74007766657463685f636f6d6d756e6974795f62616c616e6365006e717569745f776974685f68656c70006b7365745f766f75636865720c706765745f7472616e73616374696f6e7300706765745f70726f66696c655f696e666f0072636865636b5f70696e5f6d69736d61746368066a7665726966795f796f620671636f6e6669726d5f6e65775f616c6961730074696e6974696174655f7472616e73616374696f6e00696765745f706f6f6c7300694c61737456616c756560 [T] postgresdb:pg.go:118 stop single tx err= [T] engine:db.go:389 that's a wrap engine=&{0xc0003b0200 0xc000438540 0xc0004f4f00 0xc000408ac0 0xc00007f680 {160 +254722885991 root 128 0 false false : true false} 0xa3a300 true false false 0} loop exited with error: key not found: exit status 1