grassrootseconomics/sarafu-vise
8
0
Fork 0
Code Issues 18 Pull Requests 3 Actions Packages Projects Releases Wiki Activity

Verify cache behavior #30

New Issue
Open
opened 2025-02-26 16:35:32 +01:00 by lash · 8 comments
lash commented 2025-02-26 16:35:32 +01:00
Owner
Copy Link

Identify one menu location where unnecessary reload is used, and verify that the cache will provide the value without calling external function.

Once verified, gradually use this method to optimize similar menu locations.

Identify one menu location where unnecessary reload is used, and verify that the cache will provide the value without calling external function. Once verified, gradually use this method to optimize similar menu locations.
kamikazechaser added the
Kind/Enhancement
Priority
Low
 labels 2025-04-16 16:54:28 +02:00
kamikazechaser added this to the USSD project 2025-04-29 10:16:44 +02:00
Alfred-mk commented 2025-04-29 17:40:07 +02:00
Member
Copy Link

See these logs from a recent error that affected all users. The error was popping up immediately one accessed the USSD.

The error returned from the USSD was unknown symbol: manage_vouchers or any other symbol that was skipped.

Restarting the USSD resolved it, but the root cause is yet to be identified

See these logs from a recent error that affected all users. The error was popping up immediately one accessed the USSD. The error returned from the USSD was `unknown symbol: manage_vouchers` or any other symbol that was skipped. Restarting the USSD resolved it, but the root cause is yet to be identified
unknown_symbol_error.txt
14 KiB
carlos commented 2025-04-30 10:44:10 +02:00
Member
Copy Link

Logs for a similar issue encountered:

Logs for a similar issue encountered:
unknown_symbol_check_blocked_account_status.txt
20 KiB
Alfred-mk added
Kind/Bug
Priority
High
 and removed
Kind/Enhancement
Priority
Low
 labels 2025-05-07 18:39:18 +02:00
Alfred-mk commented 2025-05-15 01:18:04 +02:00
Member
Copy Link

Additional logs

Additional logs
15_may_2025.txt
21 KiB
kamikazechaser commented 2025-05-22 14:30:56 +02:00
Owner
Copy Link
ussd-1  | [D] atserver:parse.go:48 Received request:	{"body":"phoneNumber=%2B254711777734\u0026serviceCode=%2A384%2A96%23\u0026text=\u0026sessionId=ATUid_568f95774748f3efe69545fb944cc65b\u0026networkCode=63902"}=??
ussd-1  | [I] visedriver.request:base.go:68 new request	data={context.Background.WithValue(net/http context value http-server, *http.Server).WithValue(net/http context value local-addr, 172.18.0.10:7123).WithCancel.WithCancel sessionid '+254711777734', rootpath 'root', flagcount 128, language '' <nil> [] <nil> 0xc0000b42a0 false}
ussd-1  | [D] engine:db.go:214 ca	ca=&{0 4294966580 [map[check_balance:Balance: 80.17 5STAR
ussd-1  |  manage_vouchers:] map[check_account_created: check_account_status: check_blocked_status:] map[clear_temporary_value:]] map[check_account_created:2 check_account_status:0 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_current_profile_info:0 get_profile_info:0 get_suggested_alias:0 get_transactions:0 get_voucher_details:0 get_vouchers:0 invite_valid_recipient:0 request_custom_alias:0 reset_account_authorized:16 reset_allow_update:0 reset_api_call_failure:6 reset_incorrect_date_format:8 reset_invalid_pin:6 reset_others_pin:6 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_voucher:12 transaction_reset:0 update_all_profile_items:0 validate_blocked_number:6 validate_recipient:50 verify_create_pin:8 verify_new_pin:2 verify_yob:6 view_statement:0 view_voucher:80]  false}
ussd-1  | [I] persist:persist.go:126 loaded state and cache	self=persister @0xc0000b22c0 state:0xc0004f4d80 cache:0xc0001cbbc0, key=+254711777734, state=state @0xc0004f4d80 moves: 416 idx: 0 flags: 0x0453300080000000000000000000000000 path: root/main lang: eng (English)
ussd-1  | [I] vm:runner.go:63 vm created with state	state=state @0xc0004f4d80 moves: 416 idx: 0 flags: 0x0453300080000000000000000000000000 path: root/main lang: eng (English), renderer=
ussd-1  | [D] engine:db.go:329 start pre-VM check	
ussd-1  | [I] vm:runner.go:63 vm created with state	state=state @0xc0004f4d80 moves: 417 idx: 0 flags: 0x0453300080000000000000000000000000 path: root/main/_first lang: eng (English), renderer=
ussd-1  | [D] vm:runner.go:152 execute code	opcode=3, op=LOAD, code=065f666972737401000007
ussd-1  | [D] vm:runner.go:153 state=state @0xc0004f4d80 moves: 417 idx: 0 flags: 0x1053300080000000000000000000000000 path: root/main/_first lang: eng (English)
ussd-1  | [D] ussdmenuhandler:menuhandler.go:153 handler has been initialized	state=state @0xc0004f4d80 moves: 417 idx: 0 flags: 0x1053300080000000000000000000000000 path: root/main/_first lang: eng (English), cache=&{0 4294967185 [map[check_balance:Balance: 80.17 5STAR
ussd-1  |  manage_vouchers:] map[check_account_created: check_account_status: check_blocked_status:] map[check_balance:sohailge balance: 7581.92 FSPTST
ussd-1  |  clear_temporary_value: manage_vouchers:] map[]] map[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_current_profile_info:0 get_profile_info:0 get_suggested_alias:0 get_transactions:0 get_voucher_details:0 get_vouchers:0 invite_valid_recipient:0 manage_vouchers:160 request_custom_alias:0 reset_account_authorized:16 reset_allow_update:0 reset_api_call_failure:6 reset_incorrect_date_format:8 reset_invalid_pin:6 reset_others_pin:6 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:6 save_yob:32 set_back:6 set_default_voucher:8 set_language:6 set_voucher:12 transaction_reset:0 update_all_profile_items:0 validate_blocked_number:6 validate_recipient:50 verify_create_pin:8 verify_new_pin:2 verify_yob:6 view_statement:0 view_voucher:80] sohailge balance: 7581.92 FSPTST
ussd-1  |  false}, x-SessionId=+254711777734
ussd-1  | [D] cache:cache.go:72 Cache add	key=_first, size=0, limit=0
ussd-1  | [D] vm:runner.go:152 execute code	opcode=7, op=HALT, code=
ussd-1  | [D] vm:runner.go:153 state=state @0xc0004f4d80 moves: 417 idx: 0 flags: 0x1053300080000000000000000000000000 path: root/main/_first lang: eng (English)
ussd-1  | [D] vm:runner.go:440 found HALT, stopping	
ussd-1  | [D] engine:db.go:361 end pre-VM check	
ussd-1  | [D] cache:cache.go:165 Cache free	frame=3, key=_first, size=0
ussd-1  | [D] state:state.go:346 code changed (set)	code=000604726f6f74
ussd-1  | [D] engine:db.go:630 entering engine reset	state=state @0xc0004f4d80 moves: 418 idx: 0 flags: 0x0453300080000000000000000000000000 path: root/main lang: eng (English)
ussd-1  | [D] cache:cache.go:165 Cache free	frame=2, key=clear_temporary_value, size=0
ussd-1  | [D] cache:cache.go:165 Cache free	frame=2, key=manage_vouchers, size=0
ussd-1  | [D] cache:cache.go:165 Cache free	frame=2, key=check_balance, size=33
ussd-1  | [D] cache:cache.go:165 Cache free	frame=1, key=check_blocked_status, size=0
ussd-1  | [D] cache:cache.go:165 Cache free	frame=1, key=check_account_created, size=0
ussd-1  | [D] cache:cache.go:165 Cache free	frame=1, key=check_account_status, size=0
ussd-1  | [I] engine:db.go:521 new VM execution with input	input=
ussd-1  | [D] engine:db.go:530 start VM run	code=000604726f6f74
ussd-1  | [D] vm:runner.go:152 execute code	opcode=6, op=MOVE, code=04726f6f74
ussd-1  | [D] vm:runner.go:153 state=state @0xc0004f4d80 moves: 420 idx: 0 flags: 0x1053300080000000000000000000000000 path:  lang: eng (English)
ussd-1  | [D] vm:runner.go:365 loaded code	sym=root, code=000314636865636b5f626c6f636b65645f7374617475730101000414636865636b5f626c6f636b65645f737461747573000315636865636b5f6163636f756e745f637265617465640102000415636865636b5f6163636f756e745f6372656174656400010e73656c665f72657365745f70696e01290100010f626c6f636b65645f6163636f756e7401260100010f73656c6563745f6c616e67756167650108000001057465726d7301090000010a6372656174655f70696e010e00000314636865636b5f6163636f756e745f7374617475730100000414636865636b5f6163636f756e745f73746174757300010b6170695f6661696c75726501190100010f6163636f756e745f70656e64696e67010b010001046d61696e010c010007
ussd-1  | [D] vm:runner.go:152 execute code	opcode=3, op=LOAD, code=14636865636b5f626c6f636b65645f7374617475730101000414636865636b5f626c6f636b65645f737461747573000315636865636b5f6163636f756e745f637265617465640102000415636865636b5f6163636f756e745f6372656174656400010e73656c665f72657365745f70696e01290100010f626c6f636b65645f6163636f756e7401260100010f73656c6563745f6c616e67756167650108000001057465726d7301090000010a6372656174655f70696e010e00000314636865636b5f6163636f756e745f7374617475730100000414636865636b5f6163636f756e745f73746174757300010b6170695f6661696c75726501190100010f6163636f756e745f70656e64696e67010b010001046d61696e010c010007
ussd-1  | [D] vm:runner.go:153 state=state @0xc0004f4d80 moves: 421 idx: 0 flags: 0x1053300080000000000000000000000000 path: root lang: eng (English)
ussd-1  | [D] cache:cache.go:72 Cache add	key=check_blocked_status, size=0, limit=1
ussd-1  | [D] vm:runner.go:152 execute code	opcode=4, op=RELOAD, code=14636865636b5f626c6f636b65645f737461747573000315636865636b5f6163636f756e745f637265617465640102000415636865636b5f6163636f756e745f6372656174656400010e73656c665f72657365745f70696e01290100010f626c6f636b65645f6163636f756e7401260100010f73656c6563745f6c616e67756167650108000001057465726d7301090000010a6372656174655f70696e010e00000314636865636b5f6163636f756e745f7374617475730100000414636865636b5f6163636f756e745f73746174757300010b6170695f6661696c75726501190100010f6163636f756e745f70656e64696e67010b010001046d61696e010c010007
ussd-1  | [D] vm:runner.go:153 state=state @0xc0004f4d80 moves: 421 idx: 0 flags: 0x1053300080000000000000000000000000 path: root lang: eng (English)
ussd-1  | [D] vm:runner.go:152 execute code	opcode=3, op=LOAD, code=15636865636b5f6163636f756e745f637265617465640102000415636865636b5f6163636f756e745f6372656174656400010e73656c665f72657365745f70696e01290100010f626c6f636b65645f6163636f756e7401260100010f73656c6563745f6c616e67756167650108000001057465726d7301090000010a6372656174655f70696e010e00000314636865636b5f6163636f756e745f7374617475730100000414636865636b5f6163636f756e745f73746174757300010b6170695f6661696c75726501190100010f6163636f756e745f70656e64696e67010b010001046d61696e010c010007
ussd-1  | [D] vm:runner.go:153 state=state @0xc0004f4d80 moves: 421 idx: 0 flags: 0x1053300080000000000000000000000000 path: root lang: eng (English)
ussd-1  | [D] cache:cache.go:72 Cache add	key=check_account_created, size=0, limit=2
ussd-1  | [D] vm:runner.go:152 execute code	opcode=4, op=RELOAD, code=15636865636b5f6163636f756e745f6372656174656400010e73656c665f72657365745f70696e01290100010f626c6f636b65645f6163636f756e7401260100010f73656c6563745f6c616e67756167650108000001057465726d7301090000010a6372656174655f70696e010e00000314636865636b5f6163636f756e745f7374617475730100000414636865636b5f6163636f756e745f73746174757300010b6170695f6661696c75726501190100010f6163636f756e745f70656e64696e67010b010001046d61696e010c010007
ussd-1  | [D] vm:runner.go:153 state=state @0xc0004f4d80 moves: 421 idx: 0 flags: 0x1053300080000000000000000000000000 path: root lang: eng (English)
ussd-1  | [D] vm:runner.go:152 execute code	opcode=1, op=CATCH, code=0e73656c665f72657365745f70696e01290100010f626c6f636b65645f6163636f756e7401260100010f73656c6563745f6c616e67756167650108000001057465726d7301090000010a6372656174655f70696e010e00000314636865636b5f6163636f756e745f7374617475730100000414636865636b5f6163636f756e745f73746174757300010b6170695f6661696c75726501190100010f6163636f756e745f70656e64696e67010b010001046d61696e010c010007
ussd-1  | [D] vm:runner.go:153 state=state @0xc0004f4d80 moves: 421 idx: 0 flags: 0x1053300080000000000000000000000000 path: root lang: eng (English)
ussd-1  | [D] vm:runner.go:152 execute code	opcode=1, op=CATCH, code=0f626c6f636b65645f6163636f756e7401260100010f73656c6563745f6c616e67756167650108000001057465726d7301090000010a6372656174655f70696e010e00000314636865636b5f6163636f756e745f7374617475730100000414636865636b5f6163636f756e745f73746174757300010b6170695f6661696c75726501190100010f6163636f756e745f70656e64696e67010b010001046d61696e010c010007
ussd-1  | [D] vm:runner.go:153 state=state @0xc0004f4d80 moves: 421 idx: 0 flags: 0x1053300080000000000000000000000000 path: root lang: eng (English)
ussd-1  | [D] vm:runner.go:152 execute code	opcode=1, op=CATCH, code=0f73656c6563745f6c616e67756167650108000001057465726d7301090000010a6372656174655f70696e010e00000314636865636b5f6163636f756e745f7374617475730100000414636865636b5f6163636f756e745f73746174757300010b6170695f6661696c75726501190100010f6163636f756e745f70656e64696e67010b010001046d61696e010c010007
ussd-1  | [D] vm:runner.go:153 state=state @0xc0004f4d80 moves: 421 idx: 0 flags: 0x1053300080000000000000000000000000 path: root lang: eng (English)
ussd-1  | [D] vm:runner.go:152 execute code	opcode=1, op=CATCH, code=057465726d7301090000010a6372656174655f70696e010e00000314636865636b5f6163636f756e745f7374617475730100000414636865636b5f6163636f756e745f73746174757300010b6170695f6661696c75726501190100010f6163636f756e745f70656e64696e67010b010001046d61696e010c010007
ussd-1  | [D] vm:runner.go:153 state=state @0xc0004f4d80 moves: 421 idx: 0 flags: 0x1053300080000000000000000000000000 path: root lang: eng (English)
ussd-1  | [D] vm:runner.go:152 execute code	opcode=1, op=CATCH, code=0a6372656174655f70696e010e00000314636865636b5f6163636f756e745f7374617475730100000414636865636b5f6163636f756e745f73746174757300010b6170695f6661696c75726501190100010f6163636f756e745f70656e64696e67010b010001046d61696e010c010007
ussd-1  | [D] vm:runner.go:153 state=state @0xc0004f4d80 moves: 421 idx: 0 flags: 0x1053300080000000000000000000000000 path: root lang: eng (English)
ussd-1  | [D] vm:runner.go:152 execute code	opcode=3, op=LOAD, code=14636865636b5f6163636f756e745f7374617475730100000414636865636b5f6163636f756e745f73746174757300010b6170695f6661696c75726501190100010f6163636f756e745f70656e64696e67010b010001046d61696e010c010007
ussd-1  | [D] vm:runner.go:153 state=state @0xc0004f4d80 moves: 421 idx: 0 flags: 0x1053300080000000000000000000000000 path: root lang: eng (English)
ussd-1  | 2025/05/22 12:30:07 URL: http://eth-custodial:5003/api/v2/account/status/0xa316408425cF17F1827483dee621c6C3A9B5fad4 | Content-Type: application/json | Method: GET| Request Body: -
ussd-1  | 2025/05/22 12:30:07 Received response for http://eth-custodial:5003/api/v2/account/status/0xa316408425cF17F1827483dee621c6C3A9B5fad4: Status Code: 200 | Content-Type: application/json
ussd-1  | [D] cache:cache.go:72 Cache add	key=check_account_status, size=0, limit=0
ussd-1  | [D] vm:runner.go:152 execute code	opcode=4, op=RELOAD, code=14636865636b5f6163636f756e745f73746174757300010b6170695f6661696c75726501190100010f6163636f756e745f70656e64696e67010b010001046d61696e010c010007
ussd-1  | [D] vm:runner.go:153 state=state @0xc0004f4d80 moves: 421 idx: 0 flags: 0x1053300080000000000000000000000000 path: root lang: eng (English)
ussd-1  | 2025/05/22 12:30:07 URL: http://eth-custodial:5003/api/v2/account/status/0xa316408425cF17F1827483dee621c6C3A9B5fad4 | Content-Type: application/json | Method: GET| Request Body: -
ussd-1  | 2025/05/22 12:30:07 Received response for http://eth-custodial:5003/api/v2/account/status/0xa316408425cF17F1827483dee621c6C3A9B5fad4: Status Code: 200 | Content-Type: application/json
ussd-1  | [D] vm:runner.go:152 execute code	opcode=1, op=CATCH, code=0b6170695f6661696c75726501190100010f6163636f756e745f70656e64696e67010b010001046d61696e010c010007
ussd-1  | [D] vm:runner.go:153 state=state @0xc0004f4d80 moves: 421 idx: 0 flags: 0x1053300080000000000000000000000000 path: root lang: eng (English)
ussd-1  | [D] vm:runner.go:152 execute code	opcode=1, op=CATCH, code=0f6163636f756e745f70656e64696e67010b010001046d61696e010c010007
ussd-1  | [D] vm:runner.go:153 state=state @0xc0004f4d80 moves: 421 idx: 0 flags: 0x1053300080000000000000000000000000 path: root lang: eng (English)
ussd-1  | [D] vm:runner.go:152 execute code	opcode=1, op=CATCH, code=046d61696e010c010007
ussd-1  | [D] vm:runner.go:153 state=state @0xc0004f4d80 moves: 421 idx: 0 flags: 0x1053300080000000000000000000000000 path: root lang: eng (English)
ussd-1  | [I] vm:runner.go:276 catch!	flag=12, sym=main, target=main, mode=true
ussd-1  | [D] vm:runner.go:152 execute code	opcode=3, op=LOAD, code=15636c6561725f74656d706f726172795f76616c75650102000415636c6561725f74656d706f726172795f76616c756500030f6d616e6167655f766f75636865727301a000040f6d616e6167655f766f75636865727300010b6170695f6661696c75726501190100030d636865636b5f62616c616e6365018000040d636865636b5f62616c616e636500010b6170695f6661696c75726501190100050d636865636b5f62616c616e6365000a0473656e640131000a08766f7563686572730132000a076163636f756e740133000a0468656c700134000a04717569740139000700080473656e64013100080b6d795f766f756368657273013200080a6d795f6163636f756e74013300080468656c7001340008047175697401390008012e012a
ussd-1  | [D] vm:runner.go:153 state=state @0xc0004f4d80 moves: 422 idx: 0 flags: 0x1053300080000000000000000000000000 path: root/main lang: eng (English)
ussd-1  | [D] cache:cache.go:72 Cache add	key=clear_temporary_value, size=0, limit=2
ussd-1  | [D] vm:runner.go:152 execute code	opcode=4, op=RELOAD, code=15636c6561725f74656d706f726172795f76616c756500030f6d616e6167655f766f75636865727301a000040f6d616e6167655f766f75636865727300010b6170695f6661696c75726501190100030d636865636b5f62616c616e6365018000040d636865636b5f62616c616e636500010b6170695f6661696c75726501190100050d636865636b5f62616c616e6365000a0473656e640131000a08766f7563686572730132000a076163636f756e740133000a0468656c700134000a04717569740139000700080473656e64013100080b6d795f766f756368657273013200080a6d795f6163636f756e74013300080468656c7001340008047175697401390008012e012a
ussd-1  | [D] vm:runner.go:153 state=state @0xc0004f4d80 moves: 422 idx: 0 flags: 0x1053300080000000000000000000000000 path: root/main lang: eng (English)
ussd-1  | [D] vm:runner.go:152 execute code	opcode=3, op=LOAD, code=0f6d616e6167655f766f75636865727301a000040f6d616e6167655f766f75636865727300010b6170695f6661696c75726501190100030d636865636b5f62616c616e6365018000040d636865636b5f62616c616e636500010b6170695f6661696c75726501190100050d636865636b5f62616c616e6365000a0473656e640131000a08766f7563686572730132000a076163636f756e740133000a0468656c700134000a04717569740139000700080473656e64013100080b6d795f766f756368657273013200080a6d795f6163636f756e74013300080468656c7001340008047175697401390008012e012a
ussd-1  | [D] vm:runner.go:153 state=state @0xc0004f4d80 moves: 422 idx: 0 flags: 0x1053300080000000000000000000000000 path: root/main lang: eng (English)
ussd-1  | [D] vm:runner.go:311 skip already loaded symbol	symbol=manage_vouchers
ussd-1  | [D] vm:runner.go:152 execute code	opcode=4, op=RELOAD, code=0f6d616e6167655f766f75636865727300010b6170695f6661696c75726501190100030d636865636b5f62616c616e6365018000040d636865636b5f62616c616e636500010b6170695f6661696c75726501190100050d636865636b5f62616c616e6365000a0473656e640131000a08766f7563686572730132000a076163636f756e740133000a0468656c700134000a04717569740139000700080473656e64013100080b6d795f766f756368657273013200080a6d795f6163636f756e74013300080468656c7001340008047175697401390008012e012a
ussd-1  | [D] vm:runner.go:153 state=state @0xc0004f4d80 moves: 422 idx: 0 flags: 0x1053300080000000000000000000000000 path: root/main lang: eng (English)
ussd-1  | 2025/05/22 12:30:07 URL: http://ussd-data-service:5006/api/v1/holdings/0xa316408425cF17F1827483dee621c6C3A9B5fad4 | Content-Type: application/json | Method: GET| Request Body: -
ussd-1  | 2025/05/22 12:30:07 Received response for http://ussd-data-service:5006/api/v1/holdings/0xa316408425cF17F1827483dee621c6C3A9B5fad4: Status Code: 200 | Content-Type: application/json
ussd-1  | [E] engine:db.go:533 fail VM run with state	code=, state=state @0xc0004f4d80 moves: 422 idx: 0 flags: 0x1053300080000000000000000000000000 path: root/main lang: eng (English), vm=vm (0xc0007a0360) o
``` ussd-1 | [D] atserver:parse.go:48 Received request: {"body":"phoneNumber=%2B254711777734\u0026serviceCode=%2A384%2A96%23\u0026text=\u0026sessionId=ATUid_568f95774748f3efe69545fb944cc65b\u0026networkCode=63902"}=?? ussd-1 | [I] visedriver.request:base.go:68 new request data={context.Background.WithValue(net/http context value http-server, *http.Server).WithValue(net/http context value local-addr, 172.18.0.10:7123).WithCancel.WithCancel sessionid '+254711777734', rootpath 'root', flagcount 128, language '' <nil> [] <nil> 0xc0000b42a0 false} ussd-1 | [D] engine:db.go:214 ca ca=&{0 4294966580 [map[check_balance:Balance: 80.17 5STAR ussd-1 | manage_vouchers:] map[check_account_created: check_account_status: check_blocked_status:] map[clear_temporary_value:]] map[check_account_created:2 check_account_status:0 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_current_profile_info:0 get_profile_info:0 get_suggested_alias:0 get_transactions:0 get_voucher_details:0 get_vouchers:0 invite_valid_recipient:0 request_custom_alias:0 reset_account_authorized:16 reset_allow_update:0 reset_api_call_failure:6 reset_incorrect_date_format:8 reset_invalid_pin:6 reset_others_pin:6 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_voucher:12 transaction_reset:0 update_all_profile_items:0 validate_blocked_number:6 validate_recipient:50 verify_create_pin:8 verify_new_pin:2 verify_yob:6 view_statement:0 view_voucher:80] false} ussd-1 | [I] persist:persist.go:126 loaded state and cache self=persister @0xc0000b22c0 state:0xc0004f4d80 cache:0xc0001cbbc0, key=+254711777734, state=state @0xc0004f4d80 moves: 416 idx: 0 flags: 0x0453300080000000000000000000000000 path: root/main lang: eng (English) ussd-1 | [I] vm:runner.go:63 vm created with state state=state @0xc0004f4d80 moves: 416 idx: 0 flags: 0x0453300080000000000000000000000000 path: root/main lang: eng (English), renderer= ussd-1 | [D] engine:db.go:329 start pre-VM check ussd-1 | [I] vm:runner.go:63 vm created with state state=state @0xc0004f4d80 moves: 417 idx: 0 flags: 0x0453300080000000000000000000000000 path: root/main/_first lang: eng (English), renderer= ussd-1 | [D] vm:runner.go:152 execute code opcode=3, op=LOAD, code=065f666972737401000007 ussd-1 | [D] vm:runner.go:153 state=state @0xc0004f4d80 moves: 417 idx: 0 flags: 0x1053300080000000000000000000000000 path: root/main/_first lang: eng (English) ussd-1 | [D] ussdmenuhandler:menuhandler.go:153 handler has been initialized state=state @0xc0004f4d80 moves: 417 idx: 0 flags: 0x1053300080000000000000000000000000 path: root/main/_first lang: eng (English), cache=&{0 4294967185 [map[check_balance:Balance: 80.17 5STAR ussd-1 | manage_vouchers:] map[check_account_created: check_account_status: check_blocked_status:] map[check_balance:sohailge balance: 7581.92 FSPTST ussd-1 | clear_temporary_value: manage_vouchers:] map[]] map[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_current_profile_info:0 get_profile_info:0 get_suggested_alias:0 get_transactions:0 get_voucher_details:0 get_vouchers:0 invite_valid_recipient:0 manage_vouchers:160 request_custom_alias:0 reset_account_authorized:16 reset_allow_update:0 reset_api_call_failure:6 reset_incorrect_date_format:8 reset_invalid_pin:6 reset_others_pin:6 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:6 save_yob:32 set_back:6 set_default_voucher:8 set_language:6 set_voucher:12 transaction_reset:0 update_all_profile_items:0 validate_blocked_number:6 validate_recipient:50 verify_create_pin:8 verify_new_pin:2 verify_yob:6 view_statement:0 view_voucher:80] sohailge balance: 7581.92 FSPTST ussd-1 | false}, x-SessionId=+254711777734 ussd-1 | [D] cache:cache.go:72 Cache add key=_first, size=0, limit=0 ussd-1 | [D] vm:runner.go:152 execute code opcode=7, op=HALT, code= ussd-1 | [D] vm:runner.go:153 state=state @0xc0004f4d80 moves: 417 idx: 0 flags: 0x1053300080000000000000000000000000 path: root/main/_first lang: eng (English) ussd-1 | [D] vm:runner.go:440 found HALT, stopping ussd-1 | [D] engine:db.go:361 end pre-VM check ussd-1 | [D] cache:cache.go:165 Cache free frame=3, key=_first, size=0 ussd-1 | [D] state:state.go:346 code changed (set) code=000604726f6f74 ussd-1 | [D] engine:db.go:630 entering engine reset state=state @0xc0004f4d80 moves: 418 idx: 0 flags: 0x0453300080000000000000000000000000 path: root/main lang: eng (English) ussd-1 | [D] cache:cache.go:165 Cache free frame=2, key=clear_temporary_value, size=0 ussd-1 | [D] cache:cache.go:165 Cache free frame=2, key=manage_vouchers, size=0 ussd-1 | [D] cache:cache.go:165 Cache free frame=2, key=check_balance, size=33 ussd-1 | [D] cache:cache.go:165 Cache free frame=1, key=check_blocked_status, size=0 ussd-1 | [D] cache:cache.go:165 Cache free frame=1, key=check_account_created, size=0 ussd-1 | [D] cache:cache.go:165 Cache free frame=1, key=check_account_status, size=0 ussd-1 | [I] engine:db.go:521 new VM execution with input input= ussd-1 | [D] engine:db.go:530 start VM run code=000604726f6f74 ussd-1 | [D] vm:runner.go:152 execute code opcode=6, op=MOVE, code=04726f6f74 ussd-1 | [D] vm:runner.go:153 state=state @0xc0004f4d80 moves: 420 idx: 0 flags: 0x1053300080000000000000000000000000 path: lang: eng (English) ussd-1 | [D] vm:runner.go:365 loaded code sym=root, code=000314636865636b5f626c6f636b65645f7374617475730101000414636865636b5f626c6f636b65645f737461747573000315636865636b5f6163636f756e745f637265617465640102000415636865636b5f6163636f756e745f6372656174656400010e73656c665f72657365745f70696e01290100010f626c6f636b65645f6163636f756e7401260100010f73656c6563745f6c616e67756167650108000001057465726d7301090000010a6372656174655f70696e010e00000314636865636b5f6163636f756e745f7374617475730100000414636865636b5f6163636f756e745f73746174757300010b6170695f6661696c75726501190100010f6163636f756e745f70656e64696e67010b010001046d61696e010c010007 ussd-1 | [D] vm:runner.go:152 execute code opcode=3, op=LOAD, code=14636865636b5f626c6f636b65645f7374617475730101000414636865636b5f626c6f636b65645f737461747573000315636865636b5f6163636f756e745f637265617465640102000415636865636b5f6163636f756e745f6372656174656400010e73656c665f72657365745f70696e01290100010f626c6f636b65645f6163636f756e7401260100010f73656c6563745f6c616e67756167650108000001057465726d7301090000010a6372656174655f70696e010e00000314636865636b5f6163636f756e745f7374617475730100000414636865636b5f6163636f756e745f73746174757300010b6170695f6661696c75726501190100010f6163636f756e745f70656e64696e67010b010001046d61696e010c010007 ussd-1 | [D] vm:runner.go:153 state=state @0xc0004f4d80 moves: 421 idx: 0 flags: 0x1053300080000000000000000000000000 path: root lang: eng (English) ussd-1 | [D] cache:cache.go:72 Cache add key=check_blocked_status, size=0, limit=1 ussd-1 | [D] vm:runner.go:152 execute code opcode=4, op=RELOAD, code=14636865636b5f626c6f636b65645f737461747573000315636865636b5f6163636f756e745f637265617465640102000415636865636b5f6163636f756e745f6372656174656400010e73656c665f72657365745f70696e01290100010f626c6f636b65645f6163636f756e7401260100010f73656c6563745f6c616e67756167650108000001057465726d7301090000010a6372656174655f70696e010e00000314636865636b5f6163636f756e745f7374617475730100000414636865636b5f6163636f756e745f73746174757300010b6170695f6661696c75726501190100010f6163636f756e745f70656e64696e67010b010001046d61696e010c010007 ussd-1 | [D] vm:runner.go:153 state=state @0xc0004f4d80 moves: 421 idx: 0 flags: 0x1053300080000000000000000000000000 path: root lang: eng (English) ussd-1 | [D] vm:runner.go:152 execute code opcode=3, op=LOAD, code=15636865636b5f6163636f756e745f637265617465640102000415636865636b5f6163636f756e745f6372656174656400010e73656c665f72657365745f70696e01290100010f626c6f636b65645f6163636f756e7401260100010f73656c6563745f6c616e67756167650108000001057465726d7301090000010a6372656174655f70696e010e00000314636865636b5f6163636f756e745f7374617475730100000414636865636b5f6163636f756e745f73746174757300010b6170695f6661696c75726501190100010f6163636f756e745f70656e64696e67010b010001046d61696e010c010007 ussd-1 | [D] vm:runner.go:153 state=state @0xc0004f4d80 moves: 421 idx: 0 flags: 0x1053300080000000000000000000000000 path: root lang: eng (English) ussd-1 | [D] cache:cache.go:72 Cache add key=check_account_created, size=0, limit=2 ussd-1 | [D] vm:runner.go:152 execute code opcode=4, op=RELOAD, code=15636865636b5f6163636f756e745f6372656174656400010e73656c665f72657365745f70696e01290100010f626c6f636b65645f6163636f756e7401260100010f73656c6563745f6c616e67756167650108000001057465726d7301090000010a6372656174655f70696e010e00000314636865636b5f6163636f756e745f7374617475730100000414636865636b5f6163636f756e745f73746174757300010b6170695f6661696c75726501190100010f6163636f756e745f70656e64696e67010b010001046d61696e010c010007 ussd-1 | [D] vm:runner.go:153 state=state @0xc0004f4d80 moves: 421 idx: 0 flags: 0x1053300080000000000000000000000000 path: root lang: eng (English) ussd-1 | [D] vm:runner.go:152 execute code opcode=1, op=CATCH, code=0e73656c665f72657365745f70696e01290100010f626c6f636b65645f6163636f756e7401260100010f73656c6563745f6c616e67756167650108000001057465726d7301090000010a6372656174655f70696e010e00000314636865636b5f6163636f756e745f7374617475730100000414636865636b5f6163636f756e745f73746174757300010b6170695f6661696c75726501190100010f6163636f756e745f70656e64696e67010b010001046d61696e010c010007 ussd-1 | [D] vm:runner.go:153 state=state @0xc0004f4d80 moves: 421 idx: 0 flags: 0x1053300080000000000000000000000000 path: root lang: eng (English) ussd-1 | [D] vm:runner.go:152 execute code opcode=1, op=CATCH, code=0f626c6f636b65645f6163636f756e7401260100010f73656c6563745f6c616e67756167650108000001057465726d7301090000010a6372656174655f70696e010e00000314636865636b5f6163636f756e745f7374617475730100000414636865636b5f6163636f756e745f73746174757300010b6170695f6661696c75726501190100010f6163636f756e745f70656e64696e67010b010001046d61696e010c010007 ussd-1 | [D] vm:runner.go:153 state=state @0xc0004f4d80 moves: 421 idx: 0 flags: 0x1053300080000000000000000000000000 path: root lang: eng (English) ussd-1 | [D] vm:runner.go:152 execute code opcode=1, op=CATCH, code=0f73656c6563745f6c616e67756167650108000001057465726d7301090000010a6372656174655f70696e010e00000314636865636b5f6163636f756e745f7374617475730100000414636865636b5f6163636f756e745f73746174757300010b6170695f6661696c75726501190100010f6163636f756e745f70656e64696e67010b010001046d61696e010c010007 ussd-1 | [D] vm:runner.go:153 state=state @0xc0004f4d80 moves: 421 idx: 0 flags: 0x1053300080000000000000000000000000 path: root lang: eng (English) ussd-1 | [D] vm:runner.go:152 execute code opcode=1, op=CATCH, code=057465726d7301090000010a6372656174655f70696e010e00000314636865636b5f6163636f756e745f7374617475730100000414636865636b5f6163636f756e745f73746174757300010b6170695f6661696c75726501190100010f6163636f756e745f70656e64696e67010b010001046d61696e010c010007 ussd-1 | [D] vm:runner.go:153 state=state @0xc0004f4d80 moves: 421 idx: 0 flags: 0x1053300080000000000000000000000000 path: root lang: eng (English) ussd-1 | [D] vm:runner.go:152 execute code opcode=1, op=CATCH, code=0a6372656174655f70696e010e00000314636865636b5f6163636f756e745f7374617475730100000414636865636b5f6163636f756e745f73746174757300010b6170695f6661696c75726501190100010f6163636f756e745f70656e64696e67010b010001046d61696e010c010007 ussd-1 | [D] vm:runner.go:153 state=state @0xc0004f4d80 moves: 421 idx: 0 flags: 0x1053300080000000000000000000000000 path: root lang: eng (English) ussd-1 | [D] vm:runner.go:152 execute code opcode=3, op=LOAD, code=14636865636b5f6163636f756e745f7374617475730100000414636865636b5f6163636f756e745f73746174757300010b6170695f6661696c75726501190100010f6163636f756e745f70656e64696e67010b010001046d61696e010c010007 ussd-1 | [D] vm:runner.go:153 state=state @0xc0004f4d80 moves: 421 idx: 0 flags: 0x1053300080000000000000000000000000 path: root lang: eng (English) ussd-1 | 2025/05/22 12:30:07 URL: http://eth-custodial:5003/api/v2/account/status/0xa316408425cF17F1827483dee621c6C3A9B5fad4 | Content-Type: application/json | Method: GET| Request Body: - ussd-1 | 2025/05/22 12:30:07 Received response for http://eth-custodial:5003/api/v2/account/status/0xa316408425cF17F1827483dee621c6C3A9B5fad4: Status Code: 200 | Content-Type: application/json ussd-1 | [D] cache:cache.go:72 Cache add key=check_account_status, size=0, limit=0 ussd-1 | [D] vm:runner.go:152 execute code opcode=4, op=RELOAD, code=14636865636b5f6163636f756e745f73746174757300010b6170695f6661696c75726501190100010f6163636f756e745f70656e64696e67010b010001046d61696e010c010007 ussd-1 | [D] vm:runner.go:153 state=state @0xc0004f4d80 moves: 421 idx: 0 flags: 0x1053300080000000000000000000000000 path: root lang: eng (English) ussd-1 | 2025/05/22 12:30:07 URL: http://eth-custodial:5003/api/v2/account/status/0xa316408425cF17F1827483dee621c6C3A9B5fad4 | Content-Type: application/json | Method: GET| Request Body: - ussd-1 | 2025/05/22 12:30:07 Received response for http://eth-custodial:5003/api/v2/account/status/0xa316408425cF17F1827483dee621c6C3A9B5fad4: Status Code: 200 | Content-Type: application/json ussd-1 | [D] vm:runner.go:152 execute code opcode=1, op=CATCH, code=0b6170695f6661696c75726501190100010f6163636f756e745f70656e64696e67010b010001046d61696e010c010007 ussd-1 | [D] vm:runner.go:153 state=state @0xc0004f4d80 moves: 421 idx: 0 flags: 0x1053300080000000000000000000000000 path: root lang: eng (English) ussd-1 | [D] vm:runner.go:152 execute code opcode=1, op=CATCH, code=0f6163636f756e745f70656e64696e67010b010001046d61696e010c010007 ussd-1 | [D] vm:runner.go:153 state=state @0xc0004f4d80 moves: 421 idx: 0 flags: 0x1053300080000000000000000000000000 path: root lang: eng (English) ussd-1 | [D] vm:runner.go:152 execute code opcode=1, op=CATCH, code=046d61696e010c010007 ussd-1 | [D] vm:runner.go:153 state=state @0xc0004f4d80 moves: 421 idx: 0 flags: 0x1053300080000000000000000000000000 path: root lang: eng (English) ussd-1 | [I] vm:runner.go:276 catch! flag=12, sym=main, target=main, mode=true ussd-1 | [D] vm:runner.go:152 execute code opcode=3, op=LOAD, code=15636c6561725f74656d706f726172795f76616c75650102000415636c6561725f74656d706f726172795f76616c756500030f6d616e6167655f766f75636865727301a000040f6d616e6167655f766f75636865727300010b6170695f6661696c75726501190100030d636865636b5f62616c616e6365018000040d636865636b5f62616c616e636500010b6170695f6661696c75726501190100050d636865636b5f62616c616e6365000a0473656e640131000a08766f7563686572730132000a076163636f756e740133000a0468656c700134000a04717569740139000700080473656e64013100080b6d795f766f756368657273013200080a6d795f6163636f756e74013300080468656c7001340008047175697401390008012e012a ussd-1 | [D] vm:runner.go:153 state=state @0xc0004f4d80 moves: 422 idx: 0 flags: 0x1053300080000000000000000000000000 path: root/main lang: eng (English) ussd-1 | [D] cache:cache.go:72 Cache add key=clear_temporary_value, size=0, limit=2 ussd-1 | [D] vm:runner.go:152 execute code opcode=4, op=RELOAD, code=15636c6561725f74656d706f726172795f76616c756500030f6d616e6167655f766f75636865727301a000040f6d616e6167655f766f75636865727300010b6170695f6661696c75726501190100030d636865636b5f62616c616e6365018000040d636865636b5f62616c616e636500010b6170695f6661696c75726501190100050d636865636b5f62616c616e6365000a0473656e640131000a08766f7563686572730132000a076163636f756e740133000a0468656c700134000a04717569740139000700080473656e64013100080b6d795f766f756368657273013200080a6d795f6163636f756e74013300080468656c7001340008047175697401390008012e012a ussd-1 | [D] vm:runner.go:153 state=state @0xc0004f4d80 moves: 422 idx: 0 flags: 0x1053300080000000000000000000000000 path: root/main lang: eng (English) ussd-1 | [D] vm:runner.go:152 execute code opcode=3, op=LOAD, code=0f6d616e6167655f766f75636865727301a000040f6d616e6167655f766f75636865727300010b6170695f6661696c75726501190100030d636865636b5f62616c616e6365018000040d636865636b5f62616c616e636500010b6170695f6661696c75726501190100050d636865636b5f62616c616e6365000a0473656e640131000a08766f7563686572730132000a076163636f756e740133000a0468656c700134000a04717569740139000700080473656e64013100080b6d795f766f756368657273013200080a6d795f6163636f756e74013300080468656c7001340008047175697401390008012e012a ussd-1 | [D] vm:runner.go:153 state=state @0xc0004f4d80 moves: 422 idx: 0 flags: 0x1053300080000000000000000000000000 path: root/main lang: eng (English) ussd-1 | [D] vm:runner.go:311 skip already loaded symbol symbol=manage_vouchers ussd-1 | [D] vm:runner.go:152 execute code opcode=4, op=RELOAD, code=0f6d616e6167655f766f75636865727300010b6170695f6661696c75726501190100030d636865636b5f62616c616e6365018000040d636865636b5f62616c616e636500010b6170695f6661696c75726501190100050d636865636b5f62616c616e6365000a0473656e640131000a08766f7563686572730132000a076163636f756e740133000a0468656c700134000a04717569740139000700080473656e64013100080b6d795f766f756368657273013200080a6d795f6163636f756e74013300080468656c7001340008047175697401390008012e012a ussd-1 | [D] vm:runner.go:153 state=state @0xc0004f4d80 moves: 422 idx: 0 flags: 0x1053300080000000000000000000000000 path: root/main lang: eng (English) ussd-1 | 2025/05/22 12:30:07 URL: http://ussd-data-service:5006/api/v1/holdings/0xa316408425cF17F1827483dee621c6C3A9B5fad4 | Content-Type: application/json | Method: GET| Request Body: - ussd-1 | 2025/05/22 12:30:07 Received response for http://ussd-data-service:5006/api/v1/holdings/0xa316408425cF17F1827483dee621c6C3A9B5fad4: Status Code: 200 | Content-Type: application/json ussd-1 | [E] engine:db.go:533 fail VM run with state code=, state=state @0xc0004f4d80 moves: 422 idx: 0 flags: 0x1053300080000000000000000000000000 path: root/main lang: eng (English), vm=vm (0xc0007a0360) o ```
kamikazechaser added
Reviewed
Confirmed
Priority
Critical
 and removed
Priority
High
 labels 2025-05-22 14:32:41 +02:00
Alfred-mk commented 2025-05-26 16:44:51 +02:00
Member
Copy Link

Noted differences between valid requests and invalid ones during a crash.

Valid request

ussd-1  | [D] atserver:parse.go:48 Received request:    {"body":"channel=\u0026phoneNumber=%2B254724942097\u0026serviceCode=%2A483%2A061%23\u0026sessionId=DialogussSession__5609292183699199632\u0026text="}=??
ussd-1  | [I] visedriver.request:base.go:68 new request data={context.Background.WithValue(net/http context value http-server, *http.Server).WithValue(net/http context value local-addr, 172.18.0.10:7123).WithCancel.WithCancel sessionid '+254724942097', rootpath 'root', flagcount 128, language '' <nil> [] <nil> 0xc00048c0e0 false}
ussd-1  | [D] engine:db.go:214 ca       ca=&{0 0 [map[]] map[authorize_account:6 check_account_created:2 check_blocked_status:1 check_identifier:0 check_pin_mismatch:6 check_transactions:0 check_vouchers:10 confirm_new_alias:0 confirm_pin_change:0 fetch_community_balance:0 get_amount:32 get_current_profile_info: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 max_amount:40 request_custom_alias:0 reset_account_authorized:16 reset_allow_update:0 reset_incorrect:6 reset_incorrect_date_format:8 reset_invalid_pin:6 reset_others_pin:6 reset_transaction_amount:0 retrieve_blocked_number:0 save_familyname:64 save_firstname:128 save_gender:16 save_location:16 save_offerings:8 save_others_temporary_pin:6 save_yob:32 set_back:6 set_default_voucher:8 set_voucher:12 transaction_reset:0 update_all_profile_items:0 validate_amount:64 validate_blocked_number:6 validate_recipient:50 verify_new_pin:2 verify_yob:6 view_statement:0 view_voucher:80]  false}
ussd-1  | [I] persist:persist.go:126 loaded state and cache     self=persister @0xc00054c240 state:0xc00045ee00 cache:0xc000099dc0, key=+254724942097, state=state @0xc00045ee00 moves: 2671 idx: 0

Invalid request

ussd-1  | [D] atserver:parse.go:48 Received request:    {"body":"channel=\u0026phoneNumber=%2B254724942097\u0026serviceCode=%2A483%2A061%23\u0026sessionId=DialogussSession__2881809649885222734\u0026text="}=??
ussd-1  | [I] visedriver.request:base.go:68 new request data={context.Background.WithValue(net/http context value http-server, *http.Server).WithValue(net/http context value local-addr, 172.18.0.10:7123).WithCancel.WithCancel sessionid '+254724942097', rootpath 'root', flagcount 128, language '' <nil> [] <nil> 0xc0004e0000 false}
ussd-1  | [D] engine:db.go:214 ca       ca=&{0 4294963143 [map[check_balance:Salio: 5866.56 MEDENE
ussd-1  |  manage_vouchers:] map[check_account_created: check_account_status: check_blocked_status:] map[clear_temporary_value:]] map[check_account_created:2 check_account_status:0 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_profile_info:0 get_recipient:0 get_sender:64 get_suggested_alias:0 get_transactions:0 get_voucher_details:0 invite_valid_recipient:0 request_custom_alias:0 reset_api_call_failure:6 reset_incorrect_date_format:8 reset_others_pin:6 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_yob:32 set_default_voucher:8 set_voucher:12 update_all_profile_items:0 validate_amount:64 verify_create_pin:8 verify_new_pin:2 verify_yob:6 view_statement:0]  false}
ussd-1  | [I] persist:persist.go:126 loaded state and cache     self=persister @0xc0000b0040 state:0xc000696480 cache:0xc0000b0080, key=+254724942097, state=state @0xc000696480 moves: 2651 idx: 0 flags: 0x065300889f010000000000000000000000 path:  lang: eng (English)

The cache loaded when there's a downtime for the sessionId +254724942097 is ca=&{0 4294963143 [map[check_balance:Salio: 5866.56 MEDENE....
The cache loaded after a restart and subsequent valid requests for the same sessionId +254724942097 is ca=&{0 0 [map[]] map[authorize_account:6 check_account_created:2 check_blocked_status:1....

Things to note

  1. The listed data in the cache for an invalid request (Salio: 5866.56 MEDENE) is in Swahili (correct language should be English)
  2. The logged phone number does not have the MEDENE voucher

This concludes that the logged data belongs to a different sessionId and not +254724942097

The cache might therefore be improperly stored after some time, or improperly retrieved, leading to the previous symbols being stuck in the cache and skipped when the menu runs a RELOAD

Attached are the logs comparing the valid and invalid USSD request

Noted differences between valid requests and invalid ones during a crash. ### Valid request ``` ussd-1 | [D] atserver:parse.go:48 Received request: {"body":"channel=\u0026phoneNumber=%2B254724942097\u0026serviceCode=%2A483%2A061%23\u0026sessionId=DialogussSession__5609292183699199632\u0026text="}=?? ussd-1 | [I] visedriver.request:base.go:68 new request data={context.Background.WithValue(net/http context value http-server, *http.Server).WithValue(net/http context value local-addr, 172.18.0.10:7123).WithCancel.WithCancel sessionid '+254724942097', rootpath 'root', flagcount 128, language '' <nil> [] <nil> 0xc00048c0e0 false} ussd-1 | [D] engine:db.go:214 ca ca=&{0 0 [map[]] map[authorize_account:6 check_account_created:2 check_blocked_status:1 check_identifier:0 check_pin_mismatch:6 check_transactions:0 check_vouchers:10 confirm_new_alias:0 confirm_pin_change:0 fetch_community_balance:0 get_amount:32 get_current_profile_info: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 max_amount:40 request_custom_alias:0 reset_account_authorized:16 reset_allow_update:0 reset_incorrect:6 reset_incorrect_date_format:8 reset_invalid_pin:6 reset_others_pin:6 reset_transaction_amount:0 retrieve_blocked_number:0 save_familyname:64 save_firstname:128 save_gender:16 save_location:16 save_offerings:8 save_others_temporary_pin:6 save_yob:32 set_back:6 set_default_voucher:8 set_voucher:12 transaction_reset:0 update_all_profile_items:0 validate_amount:64 validate_blocked_number:6 validate_recipient:50 verify_new_pin:2 verify_yob:6 view_statement:0 view_voucher:80] false} ussd-1 | [I] persist:persist.go:126 loaded state and cache self=persister @0xc00054c240 state:0xc00045ee00 cache:0xc000099dc0, key=+254724942097, state=state @0xc00045ee00 moves: 2671 idx: 0 ``` ### Invalid request ``` ussd-1 | [D] atserver:parse.go:48 Received request: {"body":"channel=\u0026phoneNumber=%2B254724942097\u0026serviceCode=%2A483%2A061%23\u0026sessionId=DialogussSession__2881809649885222734\u0026text="}=?? ussd-1 | [I] visedriver.request:base.go:68 new request data={context.Background.WithValue(net/http context value http-server, *http.Server).WithValue(net/http context value local-addr, 172.18.0.10:7123).WithCancel.WithCancel sessionid '+254724942097', rootpath 'root', flagcount 128, language '' <nil> [] <nil> 0xc0004e0000 false} ussd-1 | [D] engine:db.go:214 ca ca=&{0 4294963143 [map[check_balance:Salio: 5866.56 MEDENE ussd-1 | manage_vouchers:] map[check_account_created: check_account_status: check_blocked_status:] map[clear_temporary_value:]] map[check_account_created:2 check_account_status:0 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_profile_info:0 get_recipient:0 get_sender:64 get_suggested_alias:0 get_transactions:0 get_voucher_details:0 invite_valid_recipient:0 request_custom_alias:0 reset_api_call_failure:6 reset_incorrect_date_format:8 reset_others_pin:6 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_yob:32 set_default_voucher:8 set_voucher:12 update_all_profile_items:0 validate_amount:64 verify_create_pin:8 verify_new_pin:2 verify_yob:6 view_statement:0] false} ussd-1 | [I] persist:persist.go:126 loaded state and cache self=persister @0xc0000b0040 state:0xc000696480 cache:0xc0000b0080, key=+254724942097, state=state @0xc000696480 moves: 2651 idx: 0 flags: 0x065300889f010000000000000000000000 path: lang: eng (English) ``` The cache loaded when there's a downtime for the sessionId `+254724942097` is `ca=&{0 4294963143 [map[check_balance:Salio: 5866.56 MEDENE....` The cache loaded after a restart and subsequent valid requests for the same sessionId `+254724942097` is `ca=&{0 0 [map[]] map[authorize_account:6 check_account_created:2 check_blocked_status:1....` ### Things to note 1. The listed data in the cache for an invalid request `(Salio: 5866.56 MEDENE)` is in Swahili (correct language should be English) 2. The logged phone number does not have the `MEDENE` voucher This concludes that the logged data belongs to a different sessionId and not `+254724942097` The cache might therefore be improperly stored after some time, or improperly retrieved, leading to the previous symbols being stuck in the cache and skipped when the menu runs a `RELOAD` Attached are the logs comparing the valid and invalid USSD request
+254724942097_logs.txt
40 KiB
Alfred-mk commented 2025-05-27 17:58:23 +02:00
Member
Copy Link

Additional logs for a crash that happens after a restart

These logs capture all requests that lead up to an error response for all incoming requests

Additional logs for a crash that happens after a restart These logs capture all requests that lead up to an error response for all incoming requests
restart_to_failure.txt
318 KiB
kamikazechaser commented 2025-06-06 09:31:05 +02:00
Owner
Copy Link

ussd-1 | [D] atserver:parse.go:48 Received request: {"body":"phoneNumber=%2B254711777734\u0026serviceCode=%2A384%2A96%23\u0026text=\u0026sessionId=ATUid_c1a625991c5c02f7a6da9522a1f61e66\u0026networkCode=63902"}=??
ussd-1 | [I] visedriver.request:base.go:68 new request data={context.Background.WithValue(net/http context value http-server, *http.Server).WithValue(net/http context value local-addr, 172.18.0.10:7123).WithCancel.WithCancel sessionid '+254711777734', rootpath 'root', flagcount 128, language '' [] 0xc0003ce2a0 false}
ussd-1 | [D] engine:db.go:214 ca ca=&{0 0 [map[]] map[authorize_account:6 check_account_created:2 check_account_status:0 check_blocked_status:1 check_identifier:0 check_pin_mismatch:6 check_transactions:0 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_profile_info:0 get_recipient:0 get_sender:64 get_suggested_alias:0 get_transactions:0 get_voucher_details:0 get_vouchers:0 initiate_transaction:0 invite_valid_recipient:0 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_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:6 save_yob:32 set_back:6 set_default_voucher:8 set_language:6 set_voucher:12 show_blocked_account: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_statement:0 view_voucher:80] false}
ussd-1 | [I] persist:persist.go:126 loaded state and cache self=persister @0xc00052b380 state:0xc00017f900 cache:0xc00052b3c0, key=+254711777734, state=state @0xc00017f900 moves: 2081 idx: 0 flags: 0x045020809f000000000000000000000000 path: lang: swa (Swahili (macrolanguage))
ussd-1 | [I] vm:runner.go:63 vm created with state state=state @0xc00017f900 moves: 2081 idx: 0 flags: 0x045020809f000000000000000000000000 path: lang: swa (Swahili (macrolanguage)), renderer=
ussd-1 | [D] engine:db.go:329 start pre-VM check
ussd-1 | [I] vm:runner.go:63 vm created with state state=state @0xc00017f900 moves: 2082 idx: 0 flags: 0x045020809f000000000000000000000000 path: _first lang: swa (Swahili (macrolanguage)), renderer=
ussd-1 | [D] vm:runner.go:152 execute code opcode=3, op=LOAD, code=065f666972737401000007
ussd-1 | [D] vm:runner.go:153 state=state @0xc00017f900 moves: 2082 idx: 0 flags: 0x105020809f000000000000000000000000 path: _first lang: swa (Swahili (macrolanguage))
ussd-1 | [D] ussdmenuhandler:menuhandler.go:153 handler has been initialized state=state @0xc00017f900 moves: 2082 idx: 0 flags: 0x105020809f000000000000000000000000 path: _first lang: swa (Swahili (macrolanguage)), cache=&{0 22 [map[check_balance:Balance: 152.31 5STAR
ussd-1 | check_vouchers: manage_vouchers:] 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_profile_info:0 get_recipient:0 get_sender:64 get_suggested_alias:0 get_transactions:0 get_voucher_details:0 get_vouchers: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_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:6 save_yob:32 set_back:6 set_default_voucher:8 set_language:6 set_voucher:12 show_blocked_account: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_statement:0 view_voucher:80] false}, x-SessionId=+254711777734
ussd-1 | [D] cache:cache.go:70 Cache add key=_first, size=0, limit=0
ussd-1 | [D] vm:runner.go:152 execute code opcode=7, op=HALT, code=
ussd-1 | [D] vm:runner.go:153 state=state @0xc00017f900 moves: 2082 idx: 0 flags: 0x105020809f000000000000000000000000 path: _first lang: swa (Swahili (macrolanguage))
ussd-1 | [D] vm:runner.go:440 found HALT, stopping
ussd-1 | [D] engine:db.go:361 end pre-VM check
ussd-1 | [D] cache:cache.go:171 Cache free frame=1, key=_first, size=0
ussd-1 | [I] engine:db.go:521 new VM execution with input input=
ussd-1 | [D] engine:db.go:530 start VM run code=0008077365745f656e6701310008077365745f73776101320008012e012a
ussd-1 | [D] vm:runner.go:152 execute code opcode=8, op=INCMP, code=077365745f656e6701310008077365745f73776101320008012e012a
ussd-1 | [D] vm:runner.go:153 state=state @0xc00017f900 moves: 2083 idx: 0 flags: 0x105020809f000000000000000000000000 path: lang: swa (Swahili (macrolanguage))
ussd-1 | [D] vm:runner.go:152 execute code opcode=8, op=INCMP, code=077365745f73776101320008012e012a
ussd-1 | [D] vm:runner.go:153 state=state @0xc00017f900 moves: 2083 idx: 0 flags: 0x115020809f000000000000000000000000 path: lang: swa (Swahili (macrolanguage))
ussd-1 | [D] vm:runner.go:152 execute code opcode=8, op=INCMP, code=012e012a
ussd-1 | [D] vm:runner.go:153 state=state @0xc00017f900 moves: 2083 idx: 0 flags: 0x115020809f000000000000000000000000 path: lang: swa (Swahili (macrolanguage))
ussd-1 | [D] vm:runner.go:399 input wildcard match input=, next=.
ussd-1 | [E] engine:db.go:533 fail VM run with state code=, state=state @0xc00017f900 moves: 2084 idx: 0 flags: 0x125020809f000000000000000000000000 path: lang: swa (Swahili (macrolanguage)), vm=vm (0xc0007538c0) ok

ussd-1 | [D] atserver:parse.go:48 Received request: {"body":"phoneNumber=%2B254711777734\u0026serviceCode=%2A384%2A96%23\u0026text=\u0026sessionId=ATUid_c1a625991c5c02f7a6da9522a1f61e66\u0026networkCode=63902"}=?? ussd-1 | [I] visedriver.request:base.go:68 new request data={context.Background.WithValue(net/http context value http-server, *http.Server).WithValue(net/http context value local-addr, 172.18.0.10:7123).WithCancel.WithCancel sessionid '+254711777734', rootpath 'root', flagcount 128, language '' <nil> [] <nil> 0xc0003ce2a0 false} ussd-1 | [D] engine:db.go:214 ca ca=&{0 0 [map[]] map[authorize_account:6 check_account_created:2 check_account_status:0 check_blocked_status:1 check_identifier:0 check_pin_mismatch:6 check_transactions:0 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_profile_info:0 get_recipient:0 get_sender:64 get_suggested_alias:0 get_transactions:0 get_voucher_details:0 get_vouchers:0 initiate_transaction:0 invite_valid_recipient:0 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_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:6 save_yob:32 set_back:6 set_default_voucher:8 set_language:6 set_voucher:12 show_blocked_account: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_statement:0 view_voucher:80] false} ussd-1 | [I] persist:persist.go:126 loaded state and cache self=persister @0xc00052b380 state:0xc00017f900 cache:0xc00052b3c0, key=+254711777734, state=state @0xc00017f900 moves: 2081 idx: 0 flags: 0x045020809f000000000000000000000000 path: lang: swa (Swahili (macrolanguage)) ussd-1 | [I] vm:runner.go:63 vm created with state state=state @0xc00017f900 moves: 2081 idx: 0 flags: 0x045020809f000000000000000000000000 path: lang: swa (Swahili (macrolanguage)), renderer= ussd-1 | [D] engine:db.go:329 start pre-VM check ussd-1 | [I] vm:runner.go:63 vm created with state state=state @0xc00017f900 moves: 2082 idx: 0 flags: 0x045020809f000000000000000000000000 path: _first lang: swa (Swahili (macrolanguage)), renderer= ussd-1 | [D] vm:runner.go:152 execute code opcode=3, op=LOAD, code=065f666972737401000007 ussd-1 | [D] vm:runner.go:153 state=state @0xc00017f900 moves: 2082 idx: 0 flags: 0x105020809f000000000000000000000000 path: _first lang: swa (Swahili (macrolanguage)) ussd-1 | [D] ussdmenuhandler:menuhandler.go:153 handler has been initialized state=state @0xc00017f900 moves: 2082 idx: 0 flags: 0x105020809f000000000000000000000000 path: _first lang: swa (Swahili (macrolanguage)), cache=&{0 22 [map[check_balance:Balance: 152.31 5STAR ussd-1 | check_vouchers: manage_vouchers:] 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_profile_info:0 get_recipient:0 get_sender:64 get_suggested_alias:0 get_transactions:0 get_voucher_details:0 get_vouchers: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_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:6 save_yob:32 set_back:6 set_default_voucher:8 set_language:6 set_voucher:12 show_blocked_account: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_statement:0 view_voucher:80] false}, x-SessionId=+254711777734 ussd-1 | [D] cache:cache.go:70 Cache add key=_first, size=0, limit=0 ussd-1 | [D] vm:runner.go:152 execute code opcode=7, op=HALT, code= ussd-1 | [D] vm:runner.go:153 state=state @0xc00017f900 moves: 2082 idx: 0 flags: 0x105020809f000000000000000000000000 path: _first lang: swa (Swahili (macrolanguage)) ussd-1 | [D] vm:runner.go:440 found HALT, stopping ussd-1 | [D] engine:db.go:361 end pre-VM check ussd-1 | [D] cache:cache.go:171 Cache free frame=1, key=_first, size=0 ussd-1 | [I] engine:db.go:521 new VM execution with input input= ussd-1 | [D] engine:db.go:530 start VM run code=0008077365745f656e6701310008077365745f73776101320008012e012a ussd-1 | [D] vm:runner.go:152 execute code opcode=8, op=INCMP, code=077365745f656e6701310008077365745f73776101320008012e012a ussd-1 | [D] vm:runner.go:153 state=state @0xc00017f900 moves: 2083 idx: 0 flags: 0x105020809f000000000000000000000000 path: lang: swa (Swahili (macrolanguage)) ussd-1 | [D] vm:runner.go:152 execute code opcode=8, op=INCMP, code=077365745f73776101320008012e012a ussd-1 | [D] vm:runner.go:153 state=state @0xc00017f900 moves: 2083 idx: 0 flags: 0x115020809f000000000000000000000000 path: lang: swa (Swahili (macrolanguage)) ussd-1 | [D] vm:runner.go:152 execute code opcode=8, op=INCMP, code=012e012a ussd-1 | [D] vm:runner.go:153 state=state @0xc00017f900 moves: 2083 idx: 0 flags: 0x115020809f000000000000000000000000 path: lang: swa (Swahili (macrolanguage)) ussd-1 | [D] vm:runner.go:399 input wildcard match input=, next=. ussd-1 | [E] engine:db.go:533 fail VM run with state code=, state=state @0xc00017f900 moves: 2084 idx: 0 flags: 0x125020809f000000000000000000000000 path: lang: swa (Swahili (macrolanguage)), vm=vm (0xc0007538c0) ok
Alfred-mk commented 2025-06-07 12:54:27 +02:00
Member
Copy Link

Resolved in https://git.grassecon.net/grassrootseconomics/sarafu-vise/releases/tag/v1.2.5-rc.2

Commit: 3b44b4b9e7

Resolved in https://git.grassecon.net/grassrootseconomics/sarafu-vise/releases/tag/v1.2.5-rc.2 Commit: https://git.grassecon.net/grassrootseconomics/sarafu-vise/commit/3b44b4b9e7bde5c7fdf39ad217ab6590c592f932
Sign in to join this conversation.
No Branch/Tag Specified
Branches Tags
Labels
Clear labels   
ussd/user-reported

Issue reported by a user while interacting with the ussd

  
Compat/Breaking

Breaking change that won't be backward compatible

  
Kind/Bug

Something is not working

  
Kind/Documentation

Documentation changes

  
Kind/Enhancement

Improve existing functionality

  
Kind/Feature

New functionality

  
Kind/Security

This is security issue

  
Kind/Testing

Issue or pull request related to testing

  
Priority
Critical
The priority is critical

  
Priority
High
The priority is high

  
Priority
Low
The priority is low

  
Priority
Medium
The priority is medium

  
Reviewed
Confirmed
Issue has been confirmed

  
Reviewed
Duplicate
This issue or pull request already exists

  
Reviewed
Invalid
Invalid issue

  
Reviewed
Won't Fix
This issue won't be fixed

  
Status
Abandoned
Somebody has started to work on this but abandoned work

  
Status
Blocked
Something is blocking this issue or pull request

  
Status
Need More Info
Feedback is required to reproduce issue or to continue work

No Label
ussd/user-reported
Compat/Breaking
Kind/Bug
Kind/Documentation
Kind/Enhancement
Kind/Feature
Kind/Security
Kind/Testing
Priority
Critical
Priority
High
Priority
Low
Priority
Medium
Reviewed
Confirmed
Reviewed
Duplicate
Reviewed
Invalid
Reviewed
Won't Fix
Status
Abandoned
Status
Blocked
Status
Need More Info
Milestone
Clear milestone
No items
No Milestone
Projects
Clear projects
No project
USSD
Assignees
Clear assignees
No Assignees
4 Participants
Notifications
Due Date
The due date is invalid or out of range. Please use the format 'yyyy-mm-dd'.

No due date set.

Dependencies

No dependencies set.

Reference: grassrootseconomics/sarafu-vise#30
No description provided.
Delete Branch "%!s()"

Deleting a branch is permanent. Although the deleted branch may continue to exist for a short time before it actually gets removed, it CANNOT be undone in most cases. Continue?