go run -tags online,logtrace cmd/africastalking/main.go [D] visedriver-config:config.go:102 conns conn=postgres://postgres:postgres@localhost:5432/migration_2, user=postgres://postgres:postgres@localhost:5432/migration_2 [I] AfricasTalking:main.go:67 start command build=dev, conn=map[0:conn: postgres://postgres:postgres@localhost:5432/migration_2, mod TXT, typ POSTGRES 1:conn: /var/www/html/golang/sarafu-vise/services/registration, mod TXT, typ FS 2:conn: postgres://postgres:postgres@localhost:5432/migration_2, mod BIN, typ POSTGRES], outputsize=160 [D] storage:storage_service.go:64 db check conn=conn: /var/www/html/golang/sarafu-vise/services/registration, mod TXT, typ FS, store=RESOURCE [I] storage:storage_service.go:120 connecting to db conn=conn: /var/www/html/golang/sarafu-vise/services/registration, mod TXT, typ FS, typ=1 [D] storage:storage_service.go:64 db check conn=conn: postgres://postgres:postgres@localhost:5432/migration_2, mod BIN, typ POSTGRES, store=USER [I] storage:storage_service.go:120 connecting to db conn=conn: postgres://postgres:postgres@localhost:5432/migration_2, mod BIN, typ POSTGRES, typ=2 [D] storage:storage_service.go:172 missing session to apply store=&{0xc00007e3b8 0xc000000600 public 0 true [] false} [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 them [D] storage:storage_service.go:64 db check conn=conn: postgres://postgres:postgres@localhost:5432/migration_2, mod TXT, typ POSTGRES, store=STATE [I] storage:storage_service.go:120 connecting to db conn=conn: postgres://postgres:postgres@localhost:5432/migration_2, mod TXT, typ POSTGRES, typ=0 [D] atserver:parse.go:48 Received request: {"body":"channel=\u0026phoneNumber=%2B254724212224\u0026serviceCode=%2A483%2A061%23\u0026sessionId=DialogussSession__10930332230861309579\u0026text="}=?? [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, 127.0.0.1:7123).WithCancel.WithCancel sessionid '+254724212224', rootpath 'root', flagcount 128, language '' [] 0xc00054a2a0 false} [T] postgresdb:pg.go:93 begin single tx err= [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 @0xc0000ec180 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 @0xc0000ec180 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:250 made db lookup key lk=102b323534373234323132323234, pfx=16 [T] postgresdb:pg.go:93 begin single tx err= [T] postgresdb:pg.go:176 get key=2b323534373234323132323234 [I] postgresdb:pg.go:129 aborting tx tx=&{0xc000012270 0xc000563158} [I] engine:db.go:253 persister load fail. trying save in case new session err=key not found: 2b323534373234323132323234, session=+254724212224 [I] persist:persist.go:100 saving state and cache self=persister @0xc00051e4c0 state:0xc0000ec180 cache:0xc000490240, key=+254724212224, state=state @0xc0000ec180 moves: 0 idx: 0 flags: 0x0000000000000000000000000000000000 path: lang: (default) [T] persist:persist.go:101 saving bytecode code= [T] db:db.go:250 made db lookup key lk=102b323534373234323132323234, pfx=16 [T] postgresdb:pg.go:93 begin single tx err= [T] postgresdb:pg.go:149 put key=2b323534373234323132323234, val=a2655374617465a764436f6465f6684578656350617468f66742697453697a6518886753697a654964780065466c616773510000000000000000000000000000000000654d6f76657300684c616e6775616765f6664d656d6f7279a569436163686553697a65006c436163686555736553697a650065436163686581a06553697a6573a0694c61737456616c756560 [T] postgresdb:pg.go:113 stop single tx err= [T] persist:persist.go:107 state and cache flushed from persister [T] db:db.go:250 made db lookup key lk=102b323534373234323132323234, pfx=16 [T] postgresdb:pg.go:93 begin single tx err= [T] postgresdb:pg.go:176 get key=2b323534373234323132323234 [T] postgresdb:pg.go:113 stop single tx err= [I] persist:persist.go:126 loaded state and cache self=persister @0xc00051e4c0 state:0xc0000ec180 cache:0xc000490240, key=+254724212224, state=state @0xc0000ec180 moves: 0 idx: 0 flags: 0x0000000000000000000000000000000000 path: lang: (default) [T] persist:persist.go:127 loaded bytecode code= [T] engine:db.go:264 set persister st=state @0xc0000ec180 moves: 0 idx: 0 flags: 0x0000000000000000000000000000000000 path: lang: (default), cac=&{0 0 [map[]] map[] false}, session=+254724212224, persister=persister @0xc00051e4c0 state:0xc0000ec180 cache:0xc000490240 [I] vm:runner.go:63 vm created with state state=state @0xc0000ec180 moves: 0 idx: 0 flags: 0x0000000000000000000000000000000000 path: lang: (default), renderer= [D] engine:db.go:329 start pre-VM check [I] vm:runner.go:63 vm created with state state=state @0xc0000ec180 moves: 1 idx: 0 flags: 0x0000000000000000000000000000000000 path: _first lang: (default), 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 @0xc0000ec180 moves: 1 idx: 0 flags: 0x1000000000000000000000000000000000 path: _first lang: (default) [D] ussdmenuhandler:menuhandler.go:146 handler has been initialized state=state @0xc0000ec180 moves: 1 idx: 0 flags: 0x1000000000000000000000000000000000 path: _first lang: (default), cache=&{0 0 [map[] map[]] map[] false}, x-SessionId=+254724212224 [D] cache:cache.go:72 Cache add key=_first, size=0, limit=0 [T] cache:cache.go:73 Cache add data value= [D] vm:runner.go:152 execute code opcode=7, op=HALT, code= [D] vm:runner.go:153 state=state @0xc0000ec180 moves: 1 idx: 0 flags: 0x1000000000000000000000000000000000 path: _first lang: (default) [D] vm:runner.go:438 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:165 Cache free frame=1, key=_first, size=0 [D] state:state.go:346 code changed (set) code=000604726f6f74 [T] engine:db.go:605 reset on pristine state is a noop [I] engine:db.go:524 new VM execution with input input= [D] engine:db.go:533 start VM run code=000604726f6f74 [T] vm:runner.go:120 new vm run [D] vm:runner.go:152 execute code opcode=6, op=MOVE, code=04726f6f74 [D] vm:runner.go:153 state=state @0xc0000ec180 moves: 2 idx: 0 flags: 0x1000000000000000000000000000000000 path: lang: (default) [T] resource:db.go:117 getcode sym=root [T] db:db.go:250 made db lookup key lk=01726f6f74, pfx=1 [T] fsdb:fs.go:108 fs get skip missing i=0 [T] fsdb:fs.go:108 fs get skip missing i=1 [T] fsdb:fs.go:111 trying fs get i=2, key=726f6f74, path=/var/www/html/golang/sarafu-vise/services/registration/1root [T] fsdb:fs.go:111 trying fs get i=3, key=726f6f74, path=/var/www/html/golang/sarafu-vise/services/registration/root.bin [D] vm:runner.go:363 loaded code sym=root, code=000314636865636b5f626c6f636b65645f7374617475730101000414636865636b5f626c6f636b65645f737461747573000315636865636b5f6163636f756e745f637265617465640102000415636865636b5f6163636f756e745f6372656174656400010e73656c665f72657365745f70696e01290100010f626c6f636b65645f6163636f756e7401260100010f73656c6563745f6c616e67756167650108000001057465726d7301090000010a6372656174655f70696e010e00000314636865636b5f6163636f756e745f7374617475730100000414636865636b5f6163636f756e745f73746174757300010b6170695f6661696c75726501190100010f6163636f756e745f70656e64696e67010b010001046d61696e010c010007 [D] vm:runner.go:152 execute code opcode=3, op=LOAD, code=14636865636b5f626c6f636b65645f7374617475730101000414636865636b5f626c6f636b65645f737461747573000315636865636b5f6163636f756e745f637265617465640102000415636865636b5f6163636f756e745f6372656174656400010e73656c665f72657365745f70696e01290100010f626c6f636b65645f6163636f756e7401260100010f73656c6563745f6c616e67756167650108000001057465726d7301090000010a6372656174655f70696e010e00000314636865636b5f6163636f756e745f7374617475730100000414636865636b5f6163636f756e745f73746174757300010b6170695f6661696c75726501190100010f6163636f756e745f70656e64696e67010b010001046d61696e010c010007 [D] vm:runner.go:153 state=state @0xc0000ec180 moves: 3 idx: 0 flags: 0x1000000000000000000000000000000000 path: root lang: (default) [T] db:db.go:250 made db lookup key lk=202b3235343732343231323232342e0017, pfx=32 [T] postgresdb:pg.go:176 get key=0017 [I] postgresdb:pg.go:129 aborting tx tx=&{0xc000012168 0xc00047ba58} [T] db:db.go:250 made db lookup key lk=202b3235343732343231323232342e0012, pfx=32 [T] postgresdb:pg.go:93 begin single tx err= [T] postgresdb:pg.go:176 get key=0012 [I] postgresdb:pg.go:129 aborting tx tx=&{0xc000012f90 0xc00047ba48} [D] cache:cache.go:72 Cache add key=check_blocked_status, size=0, limit=1 [T] cache:cache.go:73 Cache add data value= [D] vm:runner.go:152 execute code opcode=4, op=RELOAD, code=14636865636b5f626c6f636b65645f737461747573000315636865636b5f6163636f756e745f637265617465640102000415636865636b5f6163636f756e745f6372656174656400010e73656c665f72657365745f70696e01290100010f626c6f636b65645f6163636f756e7401260100010f73656c6563745f6c616e67756167650108000001057465726d7301090000010a6372656174655f70696e010e00000314636865636b5f6163636f756e745f7374617475730100000414636865636b5f6163636f756e745f73746174757300010b6170695f6661696c75726501190100010f6163636f756e745f70656e64696e67010b010001046d61696e010c010007 [D] vm:runner.go:153 state=state @0xc0000ec180 moves: 3 idx: 0 flags: 0x1000000000000000000000000000000000 path: root lang: (default) [T] db:db.go:250 made db lookup key lk=202b3235343732343231323232342e0017, pfx=32 [T] postgresdb:pg.go:93 begin single tx err= [T] postgresdb:pg.go:176 get key=0017 [I] postgresdb:pg.go:129 aborting tx tx=&{0xc0000130e0 0xc00047ba38} [T] db:db.go:250 made db lookup key lk=202b3235343732343231323232342e0012, pfx=32 [T] postgresdb:pg.go:93 begin single tx err= [T] postgresdb:pg.go:176 get key=0012 [I] postgresdb:pg.go:129 aborting tx tx=&{0xc0000131d0 0xc00047ba28} [T] render:page.go:117 mapped key=check_blocked_status [D] vm:runner.go:152 execute code opcode=3, op=LOAD, code=15636865636b5f6163636f756e745f637265617465640102000415636865636b5f6163636f756e745f6372656174656400010e73656c665f72657365745f70696e01290100010f626c6f636b65645f6163636f756e7401260100010f73656c6563745f6c616e67756167650108000001057465726d7301090000010a6372656174655f70696e010e00000314636865636b5f6163636f756e745f7374617475730100000414636865636b5f6163636f756e745f73746174757300010b6170695f6661696c75726501190100010f6163636f756e745f70656e64696e67010b010001046d61696e010c010007 [D] vm:runner.go:153 state=state @0xc0000ec180 moves: 3 idx: 0 flags: 0x1000000000000000000000000000000000 path: root lang: (default) [T] db:db.go:250 made db lookup key lk=202b3235343732343231323232342e0001, pfx=32 [T] postgresdb:pg.go:93 begin single tx err= [T] postgresdb:pg.go:176 get key=0001 [I] postgresdb:pg.go:129 aborting tx tx=&{0xc000013320 0xc00047ba18} [D] cache:cache.go:72 Cache add key=check_account_created, size=0, limit=2 [T] cache:cache.go:73 Cache add data value= [D] vm:runner.go:152 execute code opcode=4, op=RELOAD, code=15636865636b5f6163636f756e745f6372656174656400010e73656c665f72657365745f70696e01290100010f626c6f636b65645f6163636f756e7401260100010f73656c6563745f6c616e67756167650108000001057465726d7301090000010a6372656174655f70696e010e00000314636865636b5f6163636f756e745f7374617475730100000414636865636b5f6163636f756e745f73746174757300010b6170695f6661696c75726501190100010f6163636f756e745f70656e64696e67010b010001046d61696e010c010007 [D] vm:runner.go:153 state=state @0xc0000ec180 moves: 3 idx: 0 flags: 0x1000000000000000000000000000000000 path: root lang: (default) [T] db:db.go:250 made db lookup key lk=202b3235343732343231323232342e0001, pfx=32 [T] postgresdb:pg.go:93 begin single tx err= [T] postgresdb:pg.go:176 get key=0001 [I] postgresdb:pg.go:129 aborting tx tx=&{0xc000013470 0xc00047ba08} [T] render:page.go:117 mapped key=check_account_created [D] vm:runner.go:152 execute code opcode=1, op=CATCH, code=0e73656c665f72657365745f70696e01290100010f626c6f636b65645f6163636f756e7401260100010f73656c6563745f6c616e67756167650108000001057465726d7301090000010a6372656174655f70696e010e00000314636865636b5f6163636f756e745f7374617475730100000414636865636b5f6163636f756e745f73746174757300010b6170695f6661696c75726501190100010f6163636f756e745f70656e64696e67010b010001046d61696e010c010007 [D] vm:runner.go:153 state=state @0xc0000ec180 moves: 3 idx: 0 flags: 0x1000000000000000000000000000000000 path: root lang: (default) [D] vm:runner.go:152 execute code opcode=1, op=CATCH, code=0f626c6f636b65645f6163636f756e7401260100010f73656c6563745f6c616e67756167650108000001057465726d7301090000010a6372656174655f70696e010e00000314636865636b5f6163636f756e745f7374617475730100000414636865636b5f6163636f756e745f73746174757300010b6170695f6661696c75726501190100010f6163636f756e745f70656e64696e67010b010001046d61696e010c010007 [D] vm:runner.go:153 state=state @0xc0000ec180 moves: 3 idx: 0 flags: 0x1000000000000000000000000000000000 path: root lang: (default) [D] vm:runner.go:152 execute code opcode=1, op=CATCH, code=0f73656c6563745f6c616e67756167650108000001057465726d7301090000010a6372656174655f70696e010e00000314636865636b5f6163636f756e745f7374617475730100000414636865636b5f6163636f756e745f73746174757300010b6170695f6661696c75726501190100010f6163636f756e745f70656e64696e67010b010001046d61696e010c010007 [D] vm:runner.go:153 state=state @0xc0000ec180 moves: 3 idx: 0 flags: 0x1000000000000000000000000000000000 path: root lang: (default) [I] vm:runner.go:276 catch! flag=8, sym=select_language, target=select_language, mode=false [T] resource:db.go:117 getcode sym=select_language [T] db:db.go:250 made db lookup key lk=0173656c6563745f6c616e6775616765, pfx=1 [T] fsdb:fs.go:108 fs get skip missing i=0 [T] fsdb:fs.go:108 fs get skip missing i=1 [T] fsdb:fs.go:111 trying fs get i=2, key=73656c6563745f6c616e6775616765, path=/var/www/html/golang/sarafu-vise/services/registration/1select_language [T] fsdb:fs.go:111 trying fs get i=3, key=73656c6563745f6c616e6775616765, path=/var/www/html/golang/sarafu-vise/services/registration/select_language.bin [D] vm:runner.go:152 execute code opcode=10, op=MOUT, code=07656e676c6973680131000a096b6973776168696c69013200070008077365745f656e6701310008077365745f73776101320008012e012a [D] vm:runner.go:153 state=state @0xc0000ec180 moves: 4 idx: 0 flags: 0x1000000000000000000000000000000000 path: root/select_language lang: (default) [D] vm:runner.go:152 execute code opcode=10, op=MOUT, code=096b6973776168696c69013200070008077365745f656e6701310008077365745f73776101320008012e012a [D] vm:runner.go:153 state=state @0xc0000ec180 moves: 4 idx: 0 flags: 0x1000000000000000000000000000000000 path: root/select_language lang: (default) [D] vm:runner.go:152 execute code opcode=7, op=HALT, code=0008077365745f656e6701310008077365745f73776101320008012e012a [D] vm:runner.go:153 state=state @0xc0000ec180 moves: 4 idx: 0 flags: 0x1000000000000000000000000000000000 path: root/select_language lang: (default) [D] vm:runner.go:438 found HALT, stopping [D] engine:db.go:540 end VM run code=0008077365745f656e6701310008077365745f73776101320008012e012a, state=state @0xc0000ec180 moves: 4 idx: 0 flags: 0x1400000000000000000000000000000000 path: root/select_language lang: (default), vm=vm (0xc0000585a0) ok [D] state:state.go:346 code changed (set) code=0008077365745f656e6701310008077365745f73776101320008012e012a [T] engine:db.go:572 render with state state=state @0xc0000ec180 moves: 4 idx: 0 flags: 0x1400000000000000000000000000000000 path: root/select_language lang: (default) [T] render:page.go:240 no sink found sym=select_language [D] render:size.go:87 Added cursor offset=0 [T] db:db.go:245 language using ln= [T] db:db.go:250 made db lookup key lk=0473656c6563745f6c616e6775616765, pfx=4 [T] fsdb:fs.go:108 fs get skip missing i=0 [T] fsdb:fs.go:108 fs get skip missing i=1 [T] fsdb:fs.go:111 trying fs get i=2, key=73656c6563745f6c616e6775616765, path=/var/www/html/golang/sarafu-vise/services/registration/4select_language [T] fsdb:fs.go:111 trying fs get i=3, key=73656c6563745f6c616e6775616765, path=/var/www/html/golang/sarafu-vise/services/registration/select_language [D] render:page.go:175 render for index=0 [D] render:page.go:391 rendered template bytes=50 [T] db:db.go:245 language using ln= [T] db:db.go:250 made db lookup key lk=02656e676c6973685f6d656e75, pfx=2 [T] fsdb:fs.go:108 fs get skip missing i=0 [T] fsdb:fs.go:108 fs get skip missing i=1 [T] fsdb:fs.go:111 trying fs get i=2, key=656e676c6973685f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/2english_menu [T] fsdb:fs.go:111 trying fs get i=3, key=656e676c6973685f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/english_menu [T] db:db.go:245 language using ln= [T] db:db.go:250 made db lookup key lk=026b6973776168696c695f6d656e75, pfx=2 [T] fsdb:fs.go:108 fs get skip missing i=0 [T] fsdb:fs.go:108 fs get skip missing i=1 [T] fsdb:fs.go:111 trying fs get i=2, key=6b6973776168696c695f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/2kiswahili_menu [T] fsdb:fs.go:111 trying fs get i=3, key=6b6973776168696c695f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/kiswahili_menu [D] render:page.go:400 rendered menu bytes=23 [D] render:menu.go:261 applypage m=pagecount: 2 menusink: false next: false prev: false, idx=0 [D] render:menu.go:261 applypage m=pagecount: 2 menusink: false next: false prev: false, idx=1 [D] render:page.go:361 calculated pre-navigation allocation bytes=86, menusizes=[0 0 0 0] [T] render:page.go:377 nosinkvalue idx=0, value= [T] db:db.go:245 language using ln= [T] db:db.go:250 made db lookup key lk=0473656c6563745f6c616e6775616765, pfx=4 [T] fsdb:fs.go:108 fs get skip missing i=0 [T] fsdb:fs.go:108 fs get skip missing i=1 [T] fsdb:fs.go:111 trying fs get i=2, key=73656c6563745f6c616e6775616765, path=/var/www/html/golang/sarafu-vise/services/registration/4select_language [T] fsdb:fs.go:111 trying fs get i=3, key=73656c6563745f6c616e6775616765, path=/var/www/html/golang/sarafu-vise/services/registration/select_language [D] render:page.go:175 render for index=0 [D] render:page.go:391 rendered template bytes=50 [T] db:db.go:245 language using ln= [T] db:db.go:250 made db lookup key lk=02656e676c6973685f6d656e75, pfx=2 [T] fsdb:fs.go:108 fs get skip missing i=0 [T] fsdb:fs.go:108 fs get skip missing i=1 [T] fsdb:fs.go:111 trying fs get i=2, key=656e676c6973685f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/2english_menu [T] fsdb:fs.go:111 trying fs get i=3, key=656e676c6973685f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/english_menu [T] db:db.go:245 language using ln= [T] db:db.go:250 made db lookup key lk=026b6973776168696c695f6d656e75, pfx=2 [T] fsdb:fs.go:108 fs get skip missing i=0 [T] fsdb:fs.go:108 fs get skip missing i=1 [T] fsdb:fs.go:111 trying fs get i=2, key=6b6973776168696c695f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/2kiswahili_menu [T] fsdb:fs.go:111 trying fs get i=3, key=6b6973776168696c695f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/kiswahili_menu [D] render:page.go:400 rendered menu bytes=23 [I] persist:persist.go:100 saving state and cache self=persister @0xc00051e4c0 state:0xc0000ec180 cache:0xc000490240, key=+254724212224, state=state @0xc0000ec180 moves: 4 idx: 0 flags: 0x0400000000000000000000000000000000 path: root/select_language lang: (default) [T] persist:persist.go:101 saving bytecode code=0008077365745f656e6701310008077365745f73776101320008012e012a [T] db:db.go:250 made db lookup key lk=102b323534373234323132323234, pfx=16 [T] postgresdb:pg.go:93 begin single tx err= [T] postgresdb:pg.go:149 put key=2b323534373234323132323234, val=a2655374617465a764436f6465581e0008077365745f656e6701310008077365745f73776101320008012e012a6845786563506174688264726f6f746f73656c6563745f6c616e67756167656742697453697a6518886753697a654964780065466c616773510400000000000000000000000000000000654d6f76657304684c616e6775616765f6664d656d6f7279a569436163686553697a65006c436163686555736553697a650065436163686583a0a274636865636b5f626c6f636b65645f7374617475736075636865636b5f6163636f756e745f6372656174656460a06553697a6573a274636865636b5f626c6f636b65645f7374617475730175636865636b5f6163636f756e745f6372656174656402694c61737456616c756560 [T] postgresdb:pg.go:113 stop single tx err= [T] persist:persist.go:107 state and cache flushed from persister [T] engine:db.go:389 that's a wrap engine=&{0xc0000ec180 0xc000490240 0xc0000585a0 0xc00009de00 0xc00051e4c0 {160 +254724212224 root 128 0 false false : true} 0x9f6000 true false true 0} [D] atserver:parse.go:48 Received request: {"body":"channel=\u0026phoneNumber=%2B254724212224\u0026serviceCode=%2A483%2A061%23\u0026sessionId=DialogussSession__10930332230861309579\u0026text=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, 127.0.0.1:7123).WithCancel.WithCancel sessionid '+254724212224', rootpath 'root', flagcount 128, language '' [49] 0xc00054a540 false} [T] postgresdb:pg.go:93 begin single tx err= [D] engine:db.go:214 ca ca=&{0 0 [map[]] map[check_account_created:2 check_blocked_status:1] false} [T] db:db.go:250 made db lookup key lk=102b323534373234323132323234, pfx=16 [T] postgresdb:pg.go:93 begin single tx err= [T] postgresdb:pg.go:176 get key=2b323534373234323132323234 [T] postgresdb:pg.go:113 stop single tx err= [I] persist:persist.go:126 loaded state and cache self=persister @0xc00051e4c0 state:0xc0000ed480 cache:0xc000490240, key=+254724212224, state=state @0xc0000ed480 moves: 4 idx: 0 flags: 0x0400000000000000000000000000000000 path: root/select_language lang: (default) [T] persist:persist.go:127 loaded bytecode code=0008077365745f656e6701310008077365745f73776101320008012e012a [T] engine:db.go:264 set persister st=state @0xc0000ed480 moves: 4 idx: 0 flags: 0x0400000000000000000000000000000000 path: root/select_language lang: (default), cac=&{0 0 [map[] map[check_account_created: check_blocked_status:] map[]] map[check_account_created:2 check_blocked_status:1] false}, session=+254724212224, persister=persister @0xc00051e4c0 state:0xc0000ed480 cache:0xc000490240 [I] vm:runner.go:63 vm created with state state=state @0xc0000ed480 moves: 4 idx: 0 flags: 0x0400000000000000000000000000000000 path: root/select_language lang: (default), renderer= [D] engine:db.go:329 start pre-VM check [I] vm:runner.go:63 vm created with state state=state @0xc0000ed480 moves: 5 idx: 0 flags: 0x0400000000000000000000000000000000 path: root/select_language/_first lang: (default), 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 @0xc0000ed480 moves: 5 idx: 0 flags: 0x1000000000000000000000000000000000 path: root/select_language/_first lang: (default) [D] ussdmenuhandler:menuhandler.go:146 handler has been initialized state=state @0xc0000ed480 moves: 5 idx: 0 flags: 0x1000000000000000000000000000000000 path: root/select_language/_first lang: (default), cache=&{0 0 [map[] map[check_account_created: check_blocked_status:] map[] map[]] map[check_account_created:2 check_blocked_status:1] false}, x-SessionId=+254724212224 [D] cache:cache.go:72 Cache add key=_first, size=0, limit=0 [T] cache:cache.go:73 Cache add data value= [D] vm:runner.go:152 execute code opcode=7, op=HALT, code= [D] vm:runner.go:153 state=state @0xc0000ed480 moves: 5 idx: 0 flags: 0x1000000000000000000000000000000000 path: root/select_language/_first lang: (default) [D] vm:runner.go:438 found HALT, stopping [D] engine:db.go:361 end pre-VM check [T] state:state.go:319 execpath before path=[root select_language _first] [T] state:state.go:326 execpath after path=[root select_language] [D] cache:cache.go:165 Cache free frame=3, key=_first, size=0 [I] engine:db.go:524 new VM execution with input input=31 [D] engine:db.go:533 start VM run code=0008077365745f656e6701310008077365745f73776101320008012e012a [T] vm:runner.go:120 new vm run [D] vm:runner.go:152 execute code opcode=8, op=INCMP, code=077365745f656e6701310008077365745f73776101320008012e012a [D] vm:runner.go:153 state=state @0xc0000ed480 moves: 6 idx: 0 flags: 0x1000000000000000000000000000000000 path: root/select_language lang: (default) [T] vm:runner.go:394 testing sym sym=set_eng, input=31 [I] vm:runner.go:402 input match input=31, next=set_eng [T] resource:db.go:117 getcode sym=set_eng [T] db:db.go:250 made db lookup key lk=017365745f656e67, pfx=1 [T] fsdb:fs.go:108 fs get skip missing i=0 [T] fsdb:fs.go:108 fs get skip missing i=1 [T] fsdb:fs.go:111 trying fs get i=2, key=7365745f656e67, path=/var/www/html/golang/sarafu-vise/services/registration/1set_eng [T] fsdb:fs.go:111 trying fs get i=3, key=7365745f656e67, path=/var/www/html/golang/sarafu-vise/services/registration/set_eng.bin [D] vm:runner.go:426 loaded additional code next=set_eng, code=00030c7365745f6c616e6775616765010600040c7365745f6c616e67756167650001057465726d730109000006106c616e67756167655f6368616e676564 [D] vm:runner.go:152 execute code opcode=8, op=INCMP, code=077365745f73776101320008012e012a00030c7365745f6c616e6775616765010600040c7365745f6c616e67756167650001057465726d730109000006106c616e67756167655f6368616e676564 [D] vm:runner.go:153 state=state @0xc0000ed480 moves: 7 idx: 0 flags: 0x1200000000000000000000000000000000 path: root/select_language/set_eng lang: (default) [T] vm:runner.go:394 testing sym sym=set_swa, input=31 [D] vm:runner.go:152 execute code opcode=8, op=INCMP, code=012e012a00030c7365745f6c616e6775616765010600040c7365745f6c616e67756167650001057465726d730109000006106c616e67756167655f6368616e676564 [D] vm:runner.go:153 state=state @0xc0000ed480 moves: 7 idx: 0 flags: 0x1200000000000000000000000000000000 path: root/select_language/set_eng lang: (default) [T] vm:runner.go:394 testing sym sym=., input=31 [D] vm:runner.go:152 execute code opcode=3, op=LOAD, code=0c7365745f6c616e6775616765010600040c7365745f6c616e67756167650001057465726d730109000006106c616e67756167655f6368616e676564 [D] vm:runner.go:153 state=state @0xc0000ed480 moves: 7 idx: 0 flags: 0x1200000000000000000000000000000000 path: root/select_language/set_eng lang: (default) [T] db:db.go:250 made db lookup key lk=202b3235343732343231323232342e0013, pfx=32 [T] postgresdb:pg.go:149 put key=0013, val=656e67 [T] db:db.go:250 made db lookup key lk=202b3235343732343231323232342e0014, pfx=32 [T] postgresdb:pg.go:176 get key=0014 [I] postgresdb:pg.go:129 aborting tx tx=&{0xc000013d28 0xc00047b9f8} [T] db:db.go:250 made db lookup key lk=202b3235343732343231323232342e0014, pfx=32 [T] postgresdb:pg.go:93 begin single tx err= [T] postgresdb:pg.go:149 put key=0014, val=656e67 [I] state:state.go:400 language set language=eng (English) [D] cache:cache.go:72 Cache add key=set_language, size=3, limit=6 [T] cache:cache.go:73 Cache add data value=eng [D] vm:runner.go:152 execute code opcode=4, op=RELOAD, code=0c7365745f6c616e67756167650001057465726d730109000006106c616e67756167655f6368616e676564 [D] vm:runner.go:153 state=state @0xc0000ed480 moves: 7 idx: 0 flags: 0x1201000000000000000000000000000000 path: root/select_language/set_eng lang: eng (English) [T] db:db.go:250 made db lookup key lk=202b3235343732343231323232342e0013, pfx=32 [T] postgresdb:pg.go:149 put key=0013, val=656e67 [T] db:db.go:250 made db lookup key lk=202b3235343732343231323232342e0014, pfx=32 [T] postgresdb:pg.go:176 get key=0014 [I] state:state.go:400 language set language=eng (English) [T] render:page.go:117 mapped key=set_language [D] vm:runner.go:152 execute code opcode=1, op=CATCH, code=057465726d730109000006106c616e67756167655f6368616e676564 [D] vm:runner.go:153 state=state @0xc0000ed480 moves: 7 idx: 0 flags: 0x1201000000000000000000000000000000 path: root/select_language/set_eng lang: eng (English) [I] vm:runner.go:276 catch! flag=9, sym=terms, target=terms, mode=false [T] resource:db.go:117 getcode sym=terms [T] db:db.go:250 made db lookup key lk=017465726d73, pfx=1 [T] fsdb:fs.go:108 fs get skip missing i=0 [T] fsdb:fs.go:108 fs get skip missing i=1 [T] fsdb:fs.go:111 trying fs get i=2, key=7465726d73, path=/var/www/html/golang/sarafu-vise/services/registration/1terms [T] fsdb:fs.go:111 trying fs get i=3, key=7465726d73, path=/var/www/html/golang/sarafu-vise/services/registration/terms.bin [D] vm:runner.go:152 execute code opcode=10, op=MOUT, code=037965730131000a026e6f0132000700080a6372656174655f70696e013100080471756974012a [D] vm:runner.go:153 state=state @0xc0000ed480 moves: 8 idx: 0 flags: 0x1201000000000000000000000000000000 path: root/select_language/set_eng/terms lang: eng (English) [D] vm:runner.go:152 execute code opcode=10, op=MOUT, code=026e6f0132000700080a6372656174655f70696e013100080471756974012a [D] vm:runner.go:153 state=state @0xc0000ed480 moves: 8 idx: 0 flags: 0x1201000000000000000000000000000000 path: root/select_language/set_eng/terms lang: eng (English) [D] vm:runner.go:152 execute code opcode=7, op=HALT, code=00080a6372656174655f70696e013100080471756974012a [D] vm:runner.go:153 state=state @0xc0000ed480 moves: 8 idx: 0 flags: 0x1201000000000000000000000000000000 path: root/select_language/set_eng/terms lang: eng (English) [D] vm:runner.go:438 found HALT, stopping [D] engine:db.go:540 end VM run code=00080a6372656174655f70696e013100080471756974012a, state=state @0xc0000ed480 moves: 8 idx: 0 flags: 0x1601000000000000000000000000000000 path: root/select_language/set_eng/terms lang: eng (English), vm=vm (0xc000059ec0) ok [D] state:state.go:346 code changed (set) code=00080a6372656174655f70696e013100080471756974012a [T] engine:db.go:572 render with state state=state @0xc0000ed480 moves: 8 idx: 0 flags: 0x1601000000000000000000000000000000 path: root/select_language/set_eng/terms lang: eng (English) [T] render:page.go:240 no sink found sym=terms [D] render:size.go:87 Added cursor offset=0 [T] db:db.go:245 language using ln=eng (English) [T] db:db.go:250 made db lookup key lk=047465726d73, pfx=4 [T] fsdb:fs.go:111 trying fs get i=0, key=7465726d73, path=/var/www/html/golang/sarafu-vise/services/registration/4terms_eng [T] fsdb:fs.go:111 trying fs get i=1, key=7465726d73, path=/var/www/html/golang/sarafu-vise/services/registration/terms_eng [T] fsdb:fs.go:111 trying fs get i=2, key=7465726d73, path=/var/www/html/golang/sarafu-vise/services/registration/4terms [T] fsdb:fs.go:111 trying fs get i=3, key=7465726d73, path=/var/www/html/golang/sarafu-vise/services/registration/terms [D] render:page.go:175 render for index=0 [D] render:page.go:391 rendered template bytes=87 [T] db:db.go:245 language using ln=eng (English) [T] db:db.go:250 made db lookup key lk=027965735f6d656e75, pfx=2 [T] fsdb:fs.go:111 trying fs get i=0, key=7965735f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/2yes_menu_eng [T] fsdb:fs.go:111 trying fs get i=1, key=7965735f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/yes_menu_eng [T] fsdb:fs.go:111 trying fs get i=2, key=7965735f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/2yes_menu [T] fsdb:fs.go:111 trying fs get i=3, key=7965735f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/yes_menu [T] db:db.go:245 language using ln=eng (English) [T] db:db.go:250 made db lookup key lk=026e6f5f6d656e75, pfx=2 [T] fsdb:fs.go:111 trying fs get i=0, key=6e6f5f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/2no_menu_eng [T] fsdb:fs.go:111 trying fs get i=1, key=6e6f5f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/no_menu_eng [T] fsdb:fs.go:111 trying fs get i=2, key=6e6f5f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/2no_menu [T] fsdb:fs.go:111 trying fs get i=3, key=6e6f5f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/no_menu [D] render:page.go:400 rendered menu bytes=12 [D] render:menu.go:261 applypage m=pagecount: 2 menusink: false next: false prev: false, idx=0 [D] render:menu.go:261 applypage m=pagecount: 2 menusink: false next: false prev: false, idx=1 [D] render:page.go:361 calculated pre-navigation allocation bytes=60, menusizes=[0 0 0 0] [T] render:page.go:377 nosinkvalue idx=0, value= [T] db:db.go:245 language using ln=eng (English) [T] db:db.go:250 made db lookup key lk=047465726d73, pfx=4 [T] fsdb:fs.go:111 trying fs get i=0, key=7465726d73, path=/var/www/html/golang/sarafu-vise/services/registration/4terms_eng [T] fsdb:fs.go:111 trying fs get i=1, key=7465726d73, path=/var/www/html/golang/sarafu-vise/services/registration/terms_eng [T] fsdb:fs.go:111 trying fs get i=2, key=7465726d73, path=/var/www/html/golang/sarafu-vise/services/registration/4terms [T] fsdb:fs.go:111 trying fs get i=3, key=7465726d73, path=/var/www/html/golang/sarafu-vise/services/registration/terms [D] render:page.go:175 render for index=0 [D] render:page.go:391 rendered template bytes=87 [T] db:db.go:245 language using ln=eng (English) [T] db:db.go:250 made db lookup key lk=027965735f6d656e75, pfx=2 [T] fsdb:fs.go:111 trying fs get i=0, key=7965735f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/2yes_menu_eng [T] fsdb:fs.go:111 trying fs get i=1, key=7965735f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/yes_menu_eng [T] fsdb:fs.go:111 trying fs get i=2, key=7965735f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/2yes_menu [T] fsdb:fs.go:111 trying fs get i=3, key=7965735f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/yes_menu [T] db:db.go:245 language using ln=eng (English) [T] db:db.go:250 made db lookup key lk=026e6f5f6d656e75, pfx=2 [T] fsdb:fs.go:111 trying fs get i=0, key=6e6f5f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/2no_menu_eng [T] fsdb:fs.go:111 trying fs get i=1, key=6e6f5f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/no_menu_eng [T] fsdb:fs.go:111 trying fs get i=2, key=6e6f5f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/2no_menu [T] fsdb:fs.go:111 trying fs get i=3, key=6e6f5f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/no_menu [D] render:page.go:400 rendered menu bytes=12 [I] persist:persist.go:100 saving state and cache self=persister @0xc00051e4c0 state:0xc0000ed480 cache:0xc000490240, key=+254724212224, state=state @0xc0000ed480 moves: 8 idx: 0 flags: 0x0601000000000000000000000000000000 path: root/select_language/set_eng/terms lang: eng (English) [T] persist:persist.go:101 saving bytecode code=00080a6372656174655f70696e013100080471756974012a [T] db:db.go:250 made db lookup key lk=102b323534373234323132323234, pfx=16 [T] postgresdb:pg.go:93 begin single tx err= [T] postgresdb:pg.go:149 put key=2b323534373234323132323234, val=a2655374617465a764436f6465581800080a6372656174655f70696e013100080471756974012a6845786563506174688464726f6f746f73656c6563745f6c616e6775616765677365745f656e67657465726d736742697453697a6518886753697a654964780065466c616773510601000000000000000000000000000000654d6f76657308684c616e6775616765a264436f646563656e67644e616d6567456e676c697368664d656d6f7279a569436163686553697a65006c436163686555736553697a650365436163686585a0a274636865636b5f626c6f636b65645f7374617475736075636865636b5f6163636f756e745f6372656174656460a0a16c7365745f6c616e677561676563656e67a06553697a6573a374636865636b5f626c6f636b65645f7374617475730175636865636b5f6163636f756e745f63726561746564026c7365745f6c616e677561676506694c61737456616c756563656e67 [T] postgresdb:pg.go:113 stop single tx err= [T] persist:persist.go:107 state and cache flushed from persister [T] engine:db.go:389 that's a wrap engine=&{0xc0000ed480 0xc000490240 0xc000059ec0 0xc00009de00 0xc00051e4c0 {160 +254724212224 root 128 0 false false : true} 0x9f6000 true false true 0} [T] postgresdb:pg.go:123 stop multi tx err= [D] atserver:parse.go:48 Received request: {"body":"channel=\u0026phoneNumber=%2B254724212224\u0026serviceCode=%2A483%2A061%23\u0026sessionId=DialogussSession__10930332230861309579\u0026text=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, 127.0.0.1:7123).WithCancel.WithCancel sessionid '+254724212224', rootpath 'root', flagcount 128, language '' [49] 0xc0000f20e0 false} [T] postgresdb:pg.go:93 begin single tx err= [D] engine:db.go:214 ca ca=&{0 0 [map[]] map[check_account_created:2 check_blocked_status:1 set_language:6] eng false} [T] db:db.go:250 made db lookup key lk=102b323534373234323132323234, pfx=16 [T] postgresdb:pg.go:93 begin single tx err= [T] postgresdb:pg.go:176 get key=2b323534373234323132323234 [T] postgresdb:pg.go:113 stop single tx err= [I] persist:persist.go:126 loaded state and cache self=persister @0xc00051e4c0 state:0xc0000ed880 cache:0xc000490240, key=+254724212224, state=state @0xc0000ed880 moves: 8 idx: 0 flags: 0x0601000000000000000000000000000000 path: root/select_language/set_eng/terms lang: eng (English) [T] persist:persist.go:127 loaded bytecode code=00080a6372656174655f70696e013100080471756974012a [T] engine:db.go:264 set persister st=state @0xc0000ed880 moves: 8 idx: 0 flags: 0x0601000000000000000000000000000000 path: root/select_language/set_eng/terms lang: eng (English), cac=&{0 3 [map[] map[check_account_created: check_blocked_status:] map[] map[set_language:eng] map[]] map[check_account_created:2 check_blocked_status:1 set_language:6] eng false}, session=+254724212224, persister=persister @0xc00051e4c0 state:0xc0000ed880 cache:0xc000490240 [I] vm:runner.go:63 vm created with state state=state @0xc0000ed880 moves: 8 idx: 0 flags: 0x0601000000000000000000000000000000 path: root/select_language/set_eng/terms 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 @0xc0000ed880 moves: 9 idx: 0 flags: 0x0601000000000000000000000000000000 path: root/select_language/set_eng/terms/_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 @0xc0000ed880 moves: 9 idx: 0 flags: 0x1001000000000000000000000000000000 path: root/select_language/set_eng/terms/_first lang: eng (English) [D] ussdmenuhandler:menuhandler.go:146 handler has been initialized state=state @0xc0000ed880 moves: 9 idx: 0 flags: 0x1001000000000000000000000000000000 path: root/select_language/set_eng/terms/_first lang: eng (English), cache=&{0 3 [map[] map[check_account_created: check_blocked_status:] map[] map[set_language:eng] map[] map[]] map[check_account_created:2 check_blocked_status:1 set_language:6] eng false}, x-SessionId=+254724212224 [D] cache:cache.go:72 Cache add key=_first, size=0, limit=0 [T] cache:cache.go:73 Cache add data value= [D] vm:runner.go:152 execute code opcode=7, op=HALT, code= [D] vm:runner.go:153 state=state @0xc0000ed880 moves: 9 idx: 0 flags: 0x1001000000000000000000000000000000 path: root/select_language/set_eng/terms/_first lang: eng (English) [D] vm:runner.go:438 found HALT, stopping [D] engine:db.go:361 end pre-VM check [T] state:state.go:319 execpath before path=[root select_language set_eng terms _first] [T] state:state.go:326 execpath after path=[root select_language set_eng terms] [D] cache:cache.go:165 Cache free frame=5, key=_first, size=0 [I] engine:db.go:524 new VM execution with input input=31 [D] engine:db.go:533 start VM run code=00080a6372656174655f70696e013100080471756974012a [T] vm:runner.go:120 new vm run [D] vm:runner.go:152 execute code opcode=8, op=INCMP, code=0a6372656174655f70696e013100080471756974012a [D] vm:runner.go:153 state=state @0xc0000ed880 moves: 10 idx: 0 flags: 0x1001000000000000000000000000000000 path: root/select_language/set_eng/terms lang: eng (English) [T] vm:runner.go:394 testing sym sym=create_pin, input=31 [I] vm:runner.go:402 input match input=31, next=create_pin [T] resource:db.go:117 getcode sym=create_pin [T] db:db.go:250 made db lookup key lk=016372656174655f70696e, pfx=1 [T] fsdb:fs.go:108 fs get skip missing i=0 [T] fsdb:fs.go:108 fs get skip missing i=1 [T] fsdb:fs.go:111 trying fs get i=2, key=6372656174655f70696e, path=/var/www/html/golang/sarafu-vise/services/registration/1create_pin [T] fsdb:fs.go:111 trying fs get i=3, key=6372656174655f70696e, path=/var/www/html/golang/sarafu-vise/services/registration/create_pin.bin [D] vm:runner.go:426 loaded additional code next=create_pin, code=00030e6372656174655f6163636f756e7401000001176163636f756e745f6372656174696f6e5f6661696c6564010a01000a046578697401300007000804717569740130000312736176655f74656d706f726172795f70696e0106000412736176655f74656d706f726172795f70696e00010b696e76616c69645f70696e012701000812636f6e6669726d5f6372656174655f70696e012a [D] vm:runner.go:152 execute code opcode=8, op=INCMP, code=0471756974012a00030e6372656174655f6163636f756e7401000001176163636f756e745f6372656174696f6e5f6661696c6564010a01000a046578697401300007000804717569740130000312736176655f74656d706f726172795f70696e0106000412736176655f74656d706f726172795f70696e00010b696e76616c69645f70696e012701000812636f6e6669726d5f6372656174655f70696e012a [D] vm:runner.go:153 state=state @0xc0000ed880 moves: 11 idx: 0 flags: 0x1201000000000000000000000000000000 path: root/select_language/set_eng/terms/create_pin lang: eng (English) [T] vm:runner.go:394 testing sym sym=quit, input=31 [D] vm:runner.go:152 execute code opcode=3, op=LOAD, code=0e6372656174655f6163636f756e7401000001176163636f756e745f6372656174696f6e5f6661696c6564010a01000a046578697401300007000804717569740130000312736176655f74656d706f726172795f70696e0106000412736176655f74656d706f726172795f70696e00010b696e76616c69645f70696e012701000812636f6e6669726d5f6372656174655f70696e012a [D] vm:runner.go:153 state=state @0xc0000ed880 moves: 11 idx: 0 flags: 0x1201000000000000000000000000000000 path: root/select_language/set_eng/terms/create_pin lang: eng (English) [T] db:db.go:250 made db lookup key lk=202b3235343732343231323232342e0001, pfx=32 [T] postgresdb:pg.go:176 get key=0001 [I] postgresdb:pg.go:129 aborting tx tx=&{0xc0005422d0 0xc00047b9d8} [I] ussdmenuhandler:menuhandler.go:241 Creating an account because it doesn't exist x-SessionId=+254724212224 2025/04/25 13:30:07 URL: http://localhost:5003/api/v2/account/create | Content-Type: application/json | Method: POST| Request Body: - 2025/04/25 13:30:07 Received response for http://localhost:5003/api/v2/account/create: Status Code: 200 | Content-Type: application/json [T] db:db.go:250 made db lookup key lk=202b3235343732343231323232342e0015, pfx=32 [T] postgresdb:pg.go:93 begin single tx err= [T] postgresdb:pg.go:149 put key=0015, val= [T] db:db.go:250 made db lookup key lk=202b3235343732343231323232342e0000, pfx=32 [T] postgresdb:pg.go:149 put key=0000, val=63393130356434662d363834662d346230332d386530342d343436353534643932636135 [T] db:db.go:250 made db lookup key lk=202b3235343732343231323232342e0001, pfx=32 [T] postgresdb:pg.go:149 put key=0001, val=307842316442333666323234303236303130664244373035366162416534624432393230336634364665 [T] db:db.go:250 made db lookup key lk=20623164623336663232343032363031306662643730353661626165346264323932303366343666652e000f, pfx=32 [T] postgresdb:pg.go:149 put key=000f, val=2b323534373234323132323234 [D] cache:cache.go:72 Cache add key=create_account, size=0, limit=0 [T] cache:cache.go:73 Cache add data value= [D] vm:runner.go:152 execute code opcode=1, op=CATCH, code=176163636f756e745f6372656174696f6e5f6661696c6564010a01000a046578697401300007000804717569740130000312736176655f74656d706f726172795f70696e0106000412736176655f74656d706f726172795f70696e00010b696e76616c69645f70696e012701000812636f6e6669726d5f6372656174655f70696e012a [D] vm:runner.go:153 state=state @0xc0000ed880 moves: 11 idx: 0 flags: 0x1203000000000000000000000000000000 path: root/select_language/set_eng/terms/create_pin lang: eng (English) [D] vm:runner.go:152 execute code opcode=10, op=MOUT, code=046578697401300007000804717569740130000312736176655f74656d706f726172795f70696e0106000412736176655f74656d706f726172795f70696e00010b696e76616c69645f70696e012701000812636f6e6669726d5f6372656174655f70696e012a [D] vm:runner.go:153 state=state @0xc0000ed880 moves: 11 idx: 0 flags: 0x1203000000000000000000000000000000 path: root/select_language/set_eng/terms/create_pin lang: eng (English) [D] vm:runner.go:152 execute code opcode=7, op=HALT, code=000804717569740130000312736176655f74656d706f726172795f70696e0106000412736176655f74656d706f726172795f70696e00010b696e76616c69645f70696e012701000812636f6e6669726d5f6372656174655f70696e012a [D] vm:runner.go:153 state=state @0xc0000ed880 moves: 11 idx: 0 flags: 0x1203000000000000000000000000000000 path: root/select_language/set_eng/terms/create_pin lang: eng (English) [D] vm:runner.go:438 found HALT, stopping [D] engine:db.go:540 end VM run code=000804717569740130000312736176655f74656d706f726172795f70696e0106000412736176655f74656d706f726172795f70696e00010b696e76616c69645f70696e012701000812636f6e6669726d5f6372656174655f70696e012a, state=state @0xc0000ed880 moves: 11 idx: 0 flags: 0x1603000000000000000000000000000000 path: root/select_language/set_eng/terms/create_pin lang: eng (English), vm=vm (0xc000584960) ok [D] state:state.go:346 code changed (set) code=000804717569740130000312736176655f74656d706f726172795f70696e0106000412736176655f74656d706f726172795f70696e00010b696e76616c69645f70696e012701000812636f6e6669726d5f6372656174655f70696e012a [T] engine:db.go:572 render with state state=state @0xc0000ed880 moves: 11 idx: 0 flags: 0x1603000000000000000000000000000000 path: root/select_language/set_eng/terms/create_pin lang: eng (English) [T] render:page.go:240 no sink found sym=create_pin [D] render:size.go:87 Added cursor offset=0 [T] db:db.go:245 language using ln=eng (English) [T] db:db.go:250 made db lookup key lk=046372656174655f70696e, pfx=4 [T] fsdb:fs.go:111 trying fs get i=0, key=6372656174655f70696e, path=/var/www/html/golang/sarafu-vise/services/registration/4create_pin_eng [T] fsdb:fs.go:111 trying fs get i=1, key=6372656174655f70696e, path=/var/www/html/golang/sarafu-vise/services/registration/create_pin_eng [T] fsdb:fs.go:111 trying fs get i=2, key=6372656174655f70696e, path=/var/www/html/golang/sarafu-vise/services/registration/4create_pin [T] fsdb:fs.go:111 trying fs get i=3, key=6372656174655f70696e, path=/var/www/html/golang/sarafu-vise/services/registration/create_pin [D] render:page.go:175 render for index=0 [D] render:page.go:391 rendered template bytes=52 [T] db:db.go:245 language using ln=eng (English) [T] db:db.go:250 made db lookup key lk=02657869745f6d656e75, pfx=2 [T] fsdb:fs.go:111 trying fs get i=0, key=657869745f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/2exit_menu_eng [T] fsdb:fs.go:111 trying fs get i=1, key=657869745f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/exit_menu_eng [T] fsdb:fs.go:111 trying fs get i=2, key=657869745f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/2exit_menu [T] fsdb:fs.go:111 trying fs get i=3, key=657869745f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/exit_menu [D] render:page.go:400 rendered menu bytes=7 [D] render:menu.go:261 applypage m=pagecount: 2 menusink: false next: false prev: false, idx=0 [D] render:menu.go:261 applypage m=pagecount: 2 menusink: false next: false prev: false, idx=1 [D] render:page.go:361 calculated pre-navigation allocation bytes=100, menusizes=[0 0 0 0] [T] render:page.go:377 nosinkvalue idx=0, value= [T] db:db.go:245 language using ln=eng (English) [T] db:db.go:250 made db lookup key lk=046372656174655f70696e, pfx=4 [T] fsdb:fs.go:111 trying fs get i=0, key=6372656174655f70696e, path=/var/www/html/golang/sarafu-vise/services/registration/4create_pin_eng [T] fsdb:fs.go:111 trying fs get i=1, key=6372656174655f70696e, path=/var/www/html/golang/sarafu-vise/services/registration/create_pin_eng [T] fsdb:fs.go:111 trying fs get i=2, key=6372656174655f70696e, path=/var/www/html/golang/sarafu-vise/services/registration/4create_pin [T] fsdb:fs.go:111 trying fs get i=3, key=6372656174655f70696e, path=/var/www/html/golang/sarafu-vise/services/registration/create_pin [D] render:page.go:175 render for index=0 [D] render:page.go:391 rendered template bytes=52 [T] db:db.go:245 language using ln=eng (English) [T] db:db.go:250 made db lookup key lk=02657869745f6d656e75, pfx=2 [T] fsdb:fs.go:111 trying fs get i=0, key=657869745f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/2exit_menu_eng [T] fsdb:fs.go:111 trying fs get i=1, key=657869745f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/exit_menu_eng [T] fsdb:fs.go:111 trying fs get i=2, key=657869745f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/2exit_menu [T] fsdb:fs.go:111 trying fs get i=3, key=657869745f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/exit_menu [D] render:page.go:400 rendered menu bytes=7 [I] persist:persist.go:100 saving state and cache self=persister @0xc00051e4c0 state:0xc0000ed880 cache:0xc000490240, key=+254724212224, state=state @0xc0000ed880 moves: 11 idx: 0 flags: 0x0603000000000000000000000000000000 path: root/select_language/set_eng/terms/create_pin lang: eng (English) [T] persist:persist.go:101 saving bytecode code=000804717569740130000312736176655f74656d706f726172795f70696e0106000412736176655f74656d706f726172795f70696e00010b696e76616c69645f70696e012701000812636f6e6669726d5f6372656174655f70696e012a [T] db:db.go:250 made db lookup key lk=102b323534373234323132323234, pfx=16 [T] postgresdb:pg.go:93 begin single tx err= [T] postgresdb:pg.go:149 put key=2b323534373234323132323234, val=a2655374617465a764436f6465585d000804717569740130000312736176655f74656d706f726172795f70696e0106000412736176655f74656d706f726172795f70696e00010b696e76616c69645f70696e012701000812636f6e6669726d5f6372656174655f70696e012a6845786563506174688564726f6f746f73656c6563745f6c616e6775616765677365745f656e67657465726d736a6372656174655f70696e6742697453697a6518886753697a654964780065466c616773510603000000000000000000000000000000654d6f7665730b684c616e6775616765a264436f646563656e67644e616d6567456e676c697368664d656d6f7279a569436163686553697a65006c436163686555736553697a650365436163686586a0a274636865636b5f626c6f636b65645f7374617475736075636865636b5f6163636f756e745f6372656174656460a0a16c7365745f6c616e677561676563656e67a0a16e6372656174655f6163636f756e74606553697a6573a474636865636b5f626c6f636b65645f7374617475730175636865636b5f6163636f756e745f63726561746564026c7365745f6c616e6775616765066e6372656174655f6163636f756e7400694c61737456616c756560 [T] postgresdb:pg.go:113 stop single tx err= [T] persist:persist.go:107 state and cache flushed from persister [T] engine:db.go:389 that's a wrap engine=&{0xc0000ed880 0xc000490240 0xc000584960 0xc00009de00 0xc00051e4c0 {160 +254724212224 root 128 0 false false : true} 0x9f6000 true false true 0} [T] postgresdb:pg.go:123 stop multi tx err= [D] atserver:parse.go:48 Received request: {"body":"channel=\u0026phoneNumber=%2B254724212224\u0026serviceCode=%2A483%2A061%23\u0026sessionId=DialogussSession__10930332230861309579\u0026text=1212"}=?? [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, 127.0.0.1:7123).WithCancel.WithCancel sessionid '+254724212224', rootpath 'root', flagcount 128, language '' [49 50 49 50] 0xc00054a7e0 false} [T] postgresdb:pg.go:93 begin single tx err= [D] engine:db.go:214 ca ca=&{0 0 [map[]] map[check_account_created:2 check_blocked_status:1 create_account:0 set_language:6] false} [T] db:db.go:250 made db lookup key lk=102b323534373234323132323234, pfx=16 [T] postgresdb:pg.go:93 begin single tx err= [T] postgresdb:pg.go:176 get key=2b323534373234323132323234 [T] postgresdb:pg.go:113 stop single tx err= [I] persist:persist.go:126 loaded state and cache self=persister @0xc00051e4c0 state:0xc000534780 cache:0xc000490240, key=+254724212224, state=state @0xc000534780 moves: 11 idx: 0 flags: 0x0603000000000000000000000000000000 path: root/select_language/set_eng/terms/create_pin lang: eng (English) [T] persist:persist.go:127 loaded bytecode code=000804717569740130000312736176655f74656d706f726172795f70696e0106000412736176655f74656d706f726172795f70696e00010b696e76616c69645f70696e012701000812636f6e6669726d5f6372656174655f70696e012a [T] engine:db.go:264 set persister st=state @0xc000534780 moves: 11 idx: 0 flags: 0x0603000000000000000000000000000000 path: root/select_language/set_eng/terms/create_pin lang: eng (English), cac=&{0 3 [map[] map[check_account_created: check_blocked_status:] map[] map[set_language:eng] map[] map[create_account:]] map[check_account_created:2 check_blocked_status:1 create_account:0 set_language:6] false}, session=+254724212224, persister=persister @0xc00051e4c0 state:0xc000534780 cache:0xc000490240 [I] vm:runner.go:63 vm created with state state=state @0xc000534780 moves: 11 idx: 0 flags: 0x0603000000000000000000000000000000 path: root/select_language/set_eng/terms/create_pin 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 @0xc000534780 moves: 12 idx: 0 flags: 0x0603000000000000000000000000000000 path: root/select_language/set_eng/terms/create_pin/_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 @0xc000534780 moves: 12 idx: 0 flags: 0x1003000000000000000000000000000000 path: root/select_language/set_eng/terms/create_pin/_first lang: eng (English) [D] ussdmenuhandler:menuhandler.go:146 handler has been initialized state=state @0xc000534780 moves: 12 idx: 0 flags: 0x1003000000000000000000000000000000 path: root/select_language/set_eng/terms/create_pin/_first lang: eng (English), cache=&{0 3 [map[] map[check_account_created: check_blocked_status:] map[] map[set_language:eng] map[] map[create_account:] map[]] map[check_account_created:2 check_blocked_status:1 create_account:0 set_language:6] false}, x-SessionId=+254724212224 [D] cache:cache.go:72 Cache add key=_first, size=0, limit=0 [T] cache:cache.go:73 Cache add data value= [D] vm:runner.go:152 execute code opcode=7, op=HALT, code= [D] vm:runner.go:153 state=state @0xc000534780 moves: 12 idx: 0 flags: 0x1003000000000000000000000000000000 path: root/select_language/set_eng/terms/create_pin/_first lang: eng (English) [D] vm:runner.go:438 found HALT, stopping [D] engine:db.go:361 end pre-VM check [T] state:state.go:319 execpath before path=[root select_language set_eng terms create_pin _first] [T] state:state.go:326 execpath after path=[root select_language set_eng terms create_pin] [D] cache:cache.go:165 Cache free frame=6, key=_first, size=0 [I] engine:db.go:524 new VM execution with input input=31323132 [D] engine:db.go:533 start VM run code=000804717569740130000312736176655f74656d706f726172795f70696e0106000412736176655f74656d706f726172795f70696e00010b696e76616c69645f70696e012701000812636f6e6669726d5f6372656174655f70696e012a [T] vm:runner.go:120 new vm run [D] vm:runner.go:152 execute code opcode=8, op=INCMP, code=04717569740130000312736176655f74656d706f726172795f70696e0106000412736176655f74656d706f726172795f70696e00010b696e76616c69645f70696e012701000812636f6e6669726d5f6372656174655f70696e012a [D] vm:runner.go:153 state=state @0xc000534780 moves: 13 idx: 0 flags: 0x1003000000000000000000000000000000 path: root/select_language/set_eng/terms/create_pin lang: eng (English) [T] vm:runner.go:394 testing sym sym=quit, input=31323132 [D] vm:runner.go:152 execute code opcode=3, op=LOAD, code=12736176655f74656d706f726172795f70696e0106000412736176655f74656d706f726172795f70696e00010b696e76616c69645f70696e012701000812636f6e6669726d5f6372656174655f70696e012a [D] vm:runner.go:153 state=state @0xc000534780 moves: 13 idx: 0 flags: 0x1103000000000000000000000000000000 path: root/select_language/set_eng/terms/create_pin lang: eng (English) [T] db:db.go:250 made db lookup key lk=202b3235343732343231323232342e000b, pfx=32 [T] postgresdb:pg.go:149 put key=000b, val=243261243038244a4f36376c58727345456e47736c73334330724557654d65534e4b52743047783666526c38345172657852734a4f692f566f7a4e4f [D] cache:cache.go:72 Cache add key=save_temporary_pin, size=0, limit=6 [T] cache:cache.go:73 Cache add data value= [D] vm:runner.go:152 execute code opcode=4, op=RELOAD, code=12736176655f74656d706f726172795f70696e00010b696e76616c69645f70696e012701000812636f6e6669726d5f6372656174655f70696e012a [D] vm:runner.go:153 state=state @0xc000534780 moves: 13 idx: 0 flags: 0x1103000000000000000000000000000000 path: root/select_language/set_eng/terms/create_pin lang: eng (English) [T] db:db.go:250 made db lookup key lk=202b3235343732343231323232342e000b, pfx=32 [T] postgresdb:pg.go:149 put key=000b, val=2432612430382446502e336634413745536d5a4265456f324f4148472e6f4b307a336341634d68576f486a6b52796e755a4864766471576247773432 [T] render:page.go:117 mapped key=save_temporary_pin [D] vm:runner.go:152 execute code opcode=1, op=CATCH, code=0b696e76616c69645f70696e012701000812636f6e6669726d5f6372656174655f70696e012a [D] vm:runner.go:153 state=state @0xc000534780 moves: 13 idx: 0 flags: 0x1103000000000000000000000000000000 path: root/select_language/set_eng/terms/create_pin lang: eng (English) [D] vm:runner.go:152 execute code opcode=8, op=INCMP, code=12636f6e6669726d5f6372656174655f70696e012a [D] vm:runner.go:153 state=state @0xc000534780 moves: 13 idx: 0 flags: 0x1103000000000000000000000000000000 path: root/select_language/set_eng/terms/create_pin lang: eng (English) [T] vm:runner.go:394 testing sym sym=confirm_create_pin, input=31323132 [D] vm:runner.go:397 input wildcard match input=31323132, next=confirm_create_pin [T] resource:db.go:117 getcode sym=confirm_create_pin [T] db:db.go:250 made db lookup key lk=01636f6e6669726d5f6372656174655f70696e, pfx=1 [T] fsdb:fs.go:108 fs get skip missing i=0 [T] fsdb:fs.go:108 fs get skip missing i=1 [T] fsdb:fs.go:111 trying fs get i=2, key=636f6e6669726d5f6372656174655f70696e, path=/var/www/html/golang/sarafu-vise/services/registration/1confirm_create_pin [T] fsdb:fs.go:111 trying fs get i=3, key=636f6e6669726d5f6372656174655f70696e, path=/var/www/html/golang/sarafu-vise/services/registration/confirm_create_pin.bin [D] vm:runner.go:426 loaded additional code next=confirm_create_pin, code=000a046261636b013000070008015f01300003117665726966795f6372656174655f70696e01080004117665726966795f6372656174655f70696e00010c70696e5f6d69736d61746368010d010008106163636f756e745f6372656174696f6e012a [D] vm:runner.go:152 execute code opcode=10, op=MOUT, code=046261636b013000070008015f01300003117665726966795f6372656174655f70696e01080004117665726966795f6372656174655f70696e00010c70696e5f6d69736d61746368010d010008106163636f756e745f6372656174696f6e012a [D] vm:runner.go:153 state=state @0xc000534780 moves: 14 idx: 0 flags: 0x1203000000000000000000000000000000 path: root/select_language/set_eng/terms/create_pin/confirm_create_pin lang: eng (English) [D] vm:runner.go:152 execute code opcode=7, op=HALT, code=0008015f01300003117665726966795f6372656174655f70696e01080004117665726966795f6372656174655f70696e00010c70696e5f6d69736d61746368010d010008106163636f756e745f6372656174696f6e012a [D] vm:runner.go:153 state=state @0xc000534780 moves: 14 idx: 0 flags: 0x1203000000000000000000000000000000 path: root/select_language/set_eng/terms/create_pin/confirm_create_pin lang: eng (English) [D] vm:runner.go:438 found HALT, stopping [D] engine:db.go:540 end VM run code=0008015f01300003117665726966795f6372656174655f70696e01080004117665726966795f6372656174655f70696e00010c70696e5f6d69736d61746368010d010008106163636f756e745f6372656174696f6e012a, state=state @0xc000534780 moves: 14 idx: 0 flags: 0x1603000000000000000000000000000000 path: root/select_language/set_eng/terms/create_pin/confirm_create_pin lang: eng (English), vm=vm (0xc000541d40) ok [D] state:state.go:346 code changed (set) code=0008015f01300003117665726966795f6372656174655f70696e01080004117665726966795f6372656174655f70696e00010c70696e5f6d69736d61746368010d010008106163636f756e745f6372656174696f6e012a [T] engine:db.go:572 render with state state=state @0xc000534780 moves: 14 idx: 0 flags: 0x1603000000000000000000000000000000 path: root/select_language/set_eng/terms/create_pin/confirm_create_pin lang: eng (English) [T] render:page.go:240 no sink found sym=confirm_create_pin [D] render:size.go:87 Added cursor offset=0 [T] db:db.go:245 language using ln=eng (English) [T] db:db.go:250 made db lookup key lk=04636f6e6669726d5f6372656174655f70696e, pfx=4 [T] fsdb:fs.go:111 trying fs get i=0, key=636f6e6669726d5f6372656174655f70696e, path=/var/www/html/golang/sarafu-vise/services/registration/4confirm_create_pin_eng [T] fsdb:fs.go:111 trying fs get i=1, key=636f6e6669726d5f6372656174655f70696e, path=/var/www/html/golang/sarafu-vise/services/registration/confirm_create_pin_eng [T] fsdb:fs.go:111 trying fs get i=2, key=636f6e6669726d5f6372656174655f70696e, path=/var/www/html/golang/sarafu-vise/services/registration/4confirm_create_pin [T] fsdb:fs.go:111 trying fs get i=3, key=636f6e6669726d5f6372656174655f70696e, path=/var/www/html/golang/sarafu-vise/services/registration/confirm_create_pin [D] render:page.go:175 render for index=0 [D] render:page.go:391 rendered template bytes=33 [T] db:db.go:245 language using ln=eng (English) [T] db:db.go:250 made db lookup key lk=026261636b5f6d656e75, pfx=2 [T] fsdb:fs.go:111 trying fs get i=0, key=6261636b5f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/2back_menu_eng [T] fsdb:fs.go:111 trying fs get i=1, key=6261636b5f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/back_menu_eng [T] fsdb:fs.go:111 trying fs get i=2, key=6261636b5f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/2back_menu [T] fsdb:fs.go:111 trying fs get i=3, key=6261636b5f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/back_menu [D] render:page.go:400 rendered menu bytes=7 [D] render:menu.go:261 applypage m=pagecount: 2 menusink: false next: false prev: false, idx=0 [D] render:menu.go:261 applypage m=pagecount: 2 menusink: false next: false prev: false, idx=1 [D] render:page.go:361 calculated pre-navigation allocation bytes=119, menusizes=[0 0 0 0] [T] render:page.go:377 nosinkvalue idx=0, value= [T] db:db.go:245 language using ln=eng (English) [T] db:db.go:250 made db lookup key lk=04636f6e6669726d5f6372656174655f70696e, pfx=4 [T] fsdb:fs.go:111 trying fs get i=0, key=636f6e6669726d5f6372656174655f70696e, path=/var/www/html/golang/sarafu-vise/services/registration/4confirm_create_pin_eng [T] fsdb:fs.go:111 trying fs get i=1, key=636f6e6669726d5f6372656174655f70696e, path=/var/www/html/golang/sarafu-vise/services/registration/confirm_create_pin_eng [T] fsdb:fs.go:111 trying fs get i=2, key=636f6e6669726d5f6372656174655f70696e, path=/var/www/html/golang/sarafu-vise/services/registration/4confirm_create_pin [T] fsdb:fs.go:111 trying fs get i=3, key=636f6e6669726d5f6372656174655f70696e, path=/var/www/html/golang/sarafu-vise/services/registration/confirm_create_pin [D] render:page.go:175 render for index=0 [D] render:page.go:391 rendered template bytes=33 [T] db:db.go:245 language using ln=eng (English) [T] db:db.go:250 made db lookup key lk=026261636b5f6d656e75, pfx=2 [T] fsdb:fs.go:111 trying fs get i=0, key=6261636b5f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/2back_menu_eng [T] fsdb:fs.go:111 trying fs get i=1, key=6261636b5f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/back_menu_eng [T] fsdb:fs.go:111 trying fs get i=2, key=6261636b5f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/2back_menu [T] fsdb:fs.go:111 trying fs get i=3, key=6261636b5f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/back_menu [D] render:page.go:400 rendered menu bytes=7 [I] persist:persist.go:100 saving state and cache self=persister @0xc00051e4c0 state:0xc000534780 cache:0xc000490240, key=+254724212224, state=state @0xc000534780 moves: 14 idx: 0 flags: 0x0603000000000000000000000000000000 path: root/select_language/set_eng/terms/create_pin/confirm_create_pin lang: eng (English) [T] persist:persist.go:101 saving bytecode code=0008015f01300003117665726966795f6372656174655f70696e01080004117665726966795f6372656174655f70696e00010c70696e5f6d69736d61746368010d010008106163636f756e745f6372656174696f6e012a [T] db:db.go:250 made db lookup key lk=102b323534373234323132323234, pfx=16 [T] postgresdb:pg.go:93 begin single tx err= [T] postgresdb:pg.go:149 put key=2b323534373234323132323234, val=a2655374617465a764436f646558570008015f01300003117665726966795f6372656174655f70696e01080004117665726966795f6372656174655f70696e00010c70696e5f6d69736d61746368010d010008106163636f756e745f6372656174696f6e012a6845786563506174688664726f6f746f73656c6563745f6c616e6775616765677365745f656e67657465726d736a6372656174655f70696e72636f6e6669726d5f6372656174655f70696e6742697453697a6518886753697a654964780065466c616773510603000000000000000000000000000000654d6f7665730e684c616e6775616765a264436f646563656e67644e616d6567456e676c697368664d656d6f7279a569436163686553697a65006c436163686555736553697a650365436163686587a0a274636865636b5f626c6f636b65645f7374617475736075636865636b5f6163636f756e745f6372656174656460a0a16c7365745f6c616e677561676563656e67a0a26e6372656174655f6163636f756e746072736176655f74656d706f726172795f70696e60a06553697a6573a572736176655f74656d706f726172795f70696e0674636865636b5f626c6f636b65645f7374617475730175636865636b5f6163636f756e745f63726561746564026c7365745f6c616e6775616765066e6372656174655f6163636f756e7400694c61737456616c756560 [T] postgresdb:pg.go:113 stop single tx err= [T] persist:persist.go:107 state and cache flushed from persister [T] engine:db.go:389 that's a wrap engine=&{0xc000534780 0xc000490240 0xc000541d40 0xc00009de00 0xc00051e4c0 {160 +254724212224 root 128 0 false false : true} 0x9f6000 true false true 0} [T] postgresdb:pg.go:123 stop multi tx err= [D] atserver:parse.go:48 Received request: {"body":"channel=\u0026phoneNumber=%2B254724212224\u0026serviceCode=%2A483%2A061%23\u0026sessionId=DialogussSession__10930332230861309579\u0026text=1212"}=?? [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, 127.0.0.1:7123).WithCancel.WithCancel sessionid '+254724212224', rootpath 'root', flagcount 128, language '' [49 50 49 50] 0xc0000f2460 false} [T] postgresdb:pg.go:93 begin single tx err= [D] engine:db.go:214 ca ca=&{0 0 [map[]] map[check_account_created:2 check_blocked_status:1 create_account:0 save_temporary_pin:6 set_language:6] false} [T] db:db.go:250 made db lookup key lk=102b323534373234323132323234, pfx=16 [T] postgresdb:pg.go:93 begin single tx err= [T] postgresdb:pg.go:176 get key=2b323534373234323132323234 [T] postgresdb:pg.go:113 stop single tx err= [I] persist:persist.go:126 loaded state and cache self=persister @0xc00051e4c0 state:0xc0000edc80 cache:0xc000490240, key=+254724212224, state=state @0xc0000edc80 moves: 14 idx: 0 flags: 0x0603000000000000000000000000000000 path: root/select_language/set_eng/terms/create_pin/confirm_create_pin lang: eng (English) [T] persist:persist.go:127 loaded bytecode code=0008015f01300003117665726966795f6372656174655f70696e01080004117665726966795f6372656174655f70696e00010c70696e5f6d69736d61746368010d010008106163636f756e745f6372656174696f6e012a [T] engine:db.go:264 set persister st=state @0xc0000edc80 moves: 14 idx: 0 flags: 0x0603000000000000000000000000000000 path: root/select_language/set_eng/terms/create_pin/confirm_create_pin lang: eng (English), cac=&{0 3 [map[] map[check_account_created: check_blocked_status:] map[] map[set_language:eng] map[] map[create_account: save_temporary_pin:] map[]] map[check_account_created:2 check_blocked_status:1 create_account:0 save_temporary_pin:6 set_language:6] false}, session=+254724212224, persister=persister @0xc00051e4c0 state:0xc0000edc80 cache:0xc000490240 [I] vm:runner.go:63 vm created with state state=state @0xc0000edc80 moves: 14 idx: 0 flags: 0x0603000000000000000000000000000000 path: root/select_language/set_eng/terms/create_pin/confirm_create_pin 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 @0xc0000edc80 moves: 15 idx: 0 flags: 0x0603000000000000000000000000000000 path: root/select_language/set_eng/terms/create_pin/confirm_create_pin/_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 @0xc0000edc80 moves: 15 idx: 0 flags: 0x1003000000000000000000000000000000 path: root/select_language/set_eng/terms/create_pin/confirm_create_pin/_first lang: eng (English) [D] ussdmenuhandler:menuhandler.go:146 handler has been initialized state=state @0xc0000edc80 moves: 15 idx: 0 flags: 0x1003000000000000000000000000000000 path: root/select_language/set_eng/terms/create_pin/confirm_create_pin/_first lang: eng (English), cache=&{0 3 [map[] map[check_account_created: check_blocked_status:] map[] map[set_language:eng] map[] map[create_account: save_temporary_pin:] map[] map[]] map[check_account_created:2 check_blocked_status:1 create_account:0 save_temporary_pin:6 set_language:6] false}, x-SessionId=+254724212224 [D] cache:cache.go:72 Cache add key=_first, size=0, limit=0 [T] cache:cache.go:73 Cache add data value= [D] vm:runner.go:152 execute code opcode=7, op=HALT, code= [D] vm:runner.go:153 state=state @0xc0000edc80 moves: 15 idx: 0 flags: 0x1003000000000000000000000000000000 path: root/select_language/set_eng/terms/create_pin/confirm_create_pin/_first lang: eng (English) [D] vm:runner.go:438 found HALT, stopping [D] engine:db.go:361 end pre-VM check [T] state:state.go:319 execpath before path=[root select_language set_eng terms create_pin confirm_create_pin _first] [T] state:state.go:326 execpath after path=[root select_language set_eng terms create_pin confirm_create_pin] [D] cache:cache.go:165 Cache free frame=7, key=_first, size=0 [I] engine:db.go:524 new VM execution with input input=31323132 [D] engine:db.go:533 start VM run code=0008015f01300003117665726966795f6372656174655f70696e01080004117665726966795f6372656174655f70696e00010c70696e5f6d69736d61746368010d010008106163636f756e745f6372656174696f6e012a [T] vm:runner.go:120 new vm run [D] vm:runner.go:152 execute code opcode=8, op=INCMP, code=015f01300003117665726966795f6372656174655f70696e01080004117665726966795f6372656174655f70696e00010c70696e5f6d69736d61746368010d010008106163636f756e745f6372656174696f6e012a [D] vm:runner.go:153 state=state @0xc0000edc80 moves: 16 idx: 0 flags: 0x1003000000000000000000000000000000 path: root/select_language/set_eng/terms/create_pin/confirm_create_pin lang: eng (English) [T] vm:runner.go:394 testing sym sym=_, input=31323132 [D] vm:runner.go:152 execute code opcode=3, op=LOAD, code=117665726966795f6372656174655f70696e01080004117665726966795f6372656174655f70696e00010c70696e5f6d69736d61746368010d010008106163636f756e745f6372656174696f6e012a [D] vm:runner.go:153 state=state @0xc0000edc80 moves: 16 idx: 0 flags: 0x1103000000000000000000000000000000 path: root/select_language/set_eng/terms/create_pin/confirm_create_pin lang: eng (English) [T] db:db.go:250 made db lookup key lk=202b3235343732343231323232342e000b, pfx=32 [T] postgresdb:pg.go:176 get key=000b [T] db:db.go:250 made db lookup key lk=202b3235343732343231323232342e0002, pfx=32 [T] postgresdb:pg.go:149 put key=0002, val=2432612430382446502e336634413745536d5a4265456f324f4148472e6f4b307a336341634d68576f486a6b52796e755a4864766471576247773432 [D] cache:cache.go:72 Cache add key=verify_create_pin, size=0, limit=8 [T] cache:cache.go:73 Cache add data value= [D] vm:runner.go:152 execute code opcode=4, op=RELOAD, code=117665726966795f6372656174655f70696e00010c70696e5f6d69736d61746368010d010008106163636f756e745f6372656174696f6e012a [D] vm:runner.go:153 state=state @0xc0000edc80 moves: 16 idx: 0 flags: 0x1143100000000000000000000000000000 path: root/select_language/set_eng/terms/create_pin/confirm_create_pin lang: eng (English) [T] db:db.go:250 made db lookup key lk=202b3235343732343231323232342e000b, pfx=32 [T] postgresdb:pg.go:176 get key=000b [T] db:db.go:250 made db lookup key lk=202b3235343732343231323232342e0002, pfx=32 [T] postgresdb:pg.go:149 put key=0002, val=2432612430382446502e336634413745536d5a4265456f324f4148472e6f4b307a336341634d68576f486a6b52796e755a4864766471576247773432 [T] render:page.go:117 mapped key=verify_create_pin [D] vm:runner.go:152 execute code opcode=1, op=CATCH, code=0c70696e5f6d69736d61746368010d010008106163636f756e745f6372656174696f6e012a [D] vm:runner.go:153 state=state @0xc0000edc80 moves: 16 idx: 0 flags: 0x1143100000000000000000000000000000 path: root/select_language/set_eng/terms/create_pin/confirm_create_pin lang: eng (English) [D] vm:runner.go:152 execute code opcode=8, op=INCMP, code=106163636f756e745f6372656174696f6e012a [D] vm:runner.go:153 state=state @0xc0000edc80 moves: 16 idx: 0 flags: 0x1143100000000000000000000000000000 path: root/select_language/set_eng/terms/create_pin/confirm_create_pin lang: eng (English) [T] vm:runner.go:394 testing sym sym=account_creation, input=31323132 [D] vm:runner.go:397 input wildcard match input=31323132, next=account_creation [T] resource:db.go:117 getcode sym=account_creation [T] db:db.go:250 made db lookup key lk=016163636f756e745f6372656174696f6e, pfx=1 [T] fsdb:fs.go:108 fs get skip missing i=0 [T] fsdb:fs.go:108 fs get skip missing i=1 [T] fsdb:fs.go:111 trying fs get i=2, key=6163636f756e745f6372656174696f6e, path=/var/www/html/golang/sarafu-vise/services/registration/1account_creation [T] fsdb:fs.go:111 trying fs get i=3, key=6163636f756e745f6372656174696f6e, path=/var/www/html/golang/sarafu-vise/services/registration/account_creation.bin [D] vm:runner.go:426 loaded additional code next=account_creation, code=0004117665726966795f6372656174655f70696e0001136372656174655f70696e5f6d69736d61746368010d010003047175697401000007 [D] vm:runner.go:152 execute code opcode=4, op=RELOAD, code=117665726966795f6372656174655f70696e0001136372656174655f70696e5f6d69736d61746368010d010003047175697401000007 [D] vm:runner.go:153 state=state @0xc0000edc80 moves: 17 idx: 0 flags: 0x1243100000000000000000000000000000 path: root/select_language/set_eng/terms/create_pin/confirm_create_pin/account_creation lang: eng (English) [T] db:db.go:250 made db lookup key lk=202b3235343732343231323232342e000b, pfx=32 [T] postgresdb:pg.go:176 get key=000b [T] db:db.go:250 made db lookup key lk=202b3235343732343231323232342e0002, pfx=32 [T] postgresdb:pg.go:149 put key=0002, val=2432612430382446502e336634413745536d5a4265456f324f4148472e6f4b307a336341634d68576f486a6b52796e755a4864766471576247773432 [T] render:page.go:117 mapped key=verify_create_pin [D] vm:runner.go:152 execute code opcode=1, op=CATCH, code=136372656174655f70696e5f6d69736d61746368010d010003047175697401000007 [D] vm:runner.go:153 state=state @0xc0000edc80 moves: 17 idx: 0 flags: 0x1243100000000000000000000000000000 path: root/select_language/set_eng/terms/create_pin/confirm_create_pin/account_creation lang: eng (English) [D] vm:runner.go:152 execute code opcode=3, op=LOAD, code=047175697401000007 [D] vm:runner.go:153 state=state @0xc0000edc80 moves: 17 idx: 0 flags: 0x1243100000000000000000000000000000 path: root/select_language/set_eng/terms/create_pin/confirm_create_pin/account_creation lang: eng (English) [D] cache:cache.go:72 Cache add key=quit, size=36, limit=0 [T] cache:cache.go:73 Cache add data value=Thank you for using Sarafu. Goodbye! [D] vm:runner.go:152 execute code opcode=7, op=HALT, code= [D] vm:runner.go:153 state=state @0xc0000edc80 moves: 17 idx: 0 flags: 0x1243100000000000000000000000000000 path: root/select_language/set_eng/terms/create_pin/confirm_create_pin/account_creation lang: eng (English) [D] vm:runner.go:438 found HALT, stopping [D] engine:db.go:540 end VM run code=, state=state @0xc0000edc80 moves: 17 idx: 0 flags: 0x1643100000000000000000000000000000 path: root/select_language/set_eng/terms/create_pin/confirm_create_pin/account_creation lang: eng (English), vm=vm (0xc000585c80) ok [D] state:state.go:346 code changed (set) code= [I] engine:db.go:400 runner finished with no remaining code state=state @0xc0000edc80 moves: 17 idx: 0 flags: 0x1643100000000000000000000000000000 path: root/select_language/set_eng/terms/create_pin/confirm_create_pin/account_creation lang: eng (English) [D] engine:db.go:402 have output for quitting [T] engine:db.go:572 render with state state=state @0xc0000edc80 moves: 17 idx: 0 flags: 0x1643100000000000000000000000000000 path: root/select_language/set_eng/terms/create_pin/confirm_create_pin/account_creation lang: eng (English) [T] render:page.go:240 no sink found sym=account_creation [D] render:size.go:87 Added cursor offset=0 [T] db:db.go:245 language using ln=eng (English) [T] db:db.go:250 made db lookup key lk=046163636f756e745f6372656174696f6e, pfx=4 [T] fsdb:fs.go:111 trying fs get i=0, key=6163636f756e745f6372656174696f6e, path=/var/www/html/golang/sarafu-vise/services/registration/4account_creation_eng [T] fsdb:fs.go:111 trying fs get i=1, key=6163636f756e745f6372656174696f6e, path=/var/www/html/golang/sarafu-vise/services/registration/account_creation_eng [T] fsdb:fs.go:111 trying fs get i=2, key=6163636f756e745f6372656174696f6e, path=/var/www/html/golang/sarafu-vise/services/registration/4account_creation [T] fsdb:fs.go:111 trying fs get i=3, key=6163636f756e745f6372656174696f6e, path=/var/www/html/golang/sarafu-vise/services/registration/account_creation [D] render:page.go:175 render for index=0 [D] render:page.go:391 rendered template bytes=32 [D] render:page.go:400 rendered menu bytes=0 [D] render:menu.go:261 applypage m=pagecount: 2 menusink: false next: false prev: false, idx=0 [D] render:menu.go:261 applypage m=pagecount: 2 menusink: false next: false prev: false, idx=1 [D] render:page.go:361 calculated pre-navigation allocation bytes=128, menusizes=[0 0 0 0] [T] render:page.go:377 nosinkvalue idx=0, value= [T] db:db.go:245 language using ln=eng (English) [T] db:db.go:250 made db lookup key lk=046163636f756e745f6372656174696f6e, pfx=4 [T] fsdb:fs.go:111 trying fs get i=0, key=6163636f756e745f6372656174696f6e, path=/var/www/html/golang/sarafu-vise/services/registration/4account_creation_eng [T] fsdb:fs.go:111 trying fs get i=1, key=6163636f756e745f6372656174696f6e, path=/var/www/html/golang/sarafu-vise/services/registration/account_creation_eng [T] fsdb:fs.go:111 trying fs get i=2, key=6163636f756e745f6372656174696f6e, path=/var/www/html/golang/sarafu-vise/services/registration/4account_creation [T] fsdb:fs.go:111 trying fs get i=3, key=6163636f756e745f6372656174696f6e, path=/var/www/html/golang/sarafu-vise/services/registration/account_creation [D] render:page.go:175 render for index=0 [D] render:page.go:391 rendered template bytes=32 [D] render:page.go:400 rendered menu bytes=0 [T] engine:db.go:587 have exit exit=Thank you for using Sarafu. Goodbye! [D] engine:db.go:633 entering engine reset state=state @0xc0000edc80 moves: 17 idx: 0 flags: 0x0643100000000000000000000000000000 path: root/select_language/set_eng/terms/create_pin/confirm_create_pin/account_creation lang: eng (English) [T] state:state.go:319 execpath before path=[root select_language set_eng terms create_pin confirm_create_pin account_creation] [T] state:state.go:326 execpath after path=[root select_language set_eng terms create_pin confirm_create_pin] [D] cache:cache.go:165 Cache free frame=7, key=quit, size=36 [T] state:state.go:319 execpath before path=[root select_language set_eng terms create_pin confirm_create_pin] [T] state:state.go:326 execpath after path=[root select_language set_eng terms create_pin] [D] cache:cache.go:165 Cache free frame=6, key=verify_create_pin, size=0 [T] state:state.go:319 execpath before path=[root select_language set_eng terms create_pin] [T] state:state.go:326 execpath after path=[root select_language set_eng terms] [D] cache:cache.go:165 Cache free frame=5, key=create_account, size=0 [D] cache:cache.go:165 Cache free frame=5, key=save_temporary_pin, size=0 [T] state:state.go:319 execpath before path=[root select_language set_eng terms] [T] state:state.go:326 execpath after path=[root select_language set_eng] [T] state:state.go:319 execpath before path=[root select_language set_eng] [T] state:state.go:326 execpath after path=[root select_language] [D] cache:cache.go:165 Cache free frame=3, key=set_language, size=3 [T] state:state.go:319 execpath before path=[root select_language] [T] state:state.go:326 execpath after path=[root] [T] state:state.go:319 execpath before path=[root] [T] state:state.go:326 execpath after path=[] [D] cache:cache.go:165 Cache free frame=1, key=check_blocked_status, size=0 [D] cache:cache.go:165 Cache free frame=1, key=check_account_created, size=0 [I] persist:persist.go:100 saving state and cache self=persister @0xc00051e4c0 state:0xc0000edc80 cache:0xc000490240, key=+254724212224, state=state @0xc0000edc80 moves: 24 idx: 0 flags: 0x0643100000000000000000000000000000 path: lang: eng (English) [T] persist:persist.go:101 saving bytecode code= [T] db:db.go:250 made db lookup key lk=102b323534373234323132323234, pfx=16 [T] postgresdb:pg.go:93 begin single tx err= [T] postgresdb:pg.go:149 put key=2b323534373234323132323234, val=a2655374617465a764436f646540684578656350617468806742697453697a6518886753697a654964780065466c616773510643100000000000000000000000000000654d6f7665731818684c616e6775616765a264436f646563656e67644e616d6567456e676c697368664d656d6f7279a569436163686553697a65006c436163686555736553697a650065436163686581a06553697a6573a0694c61737456616c756560 [T] postgresdb:pg.go:113 stop single tx err= [T] persist:persist.go:107 state and cache flushed from persister [T] engine:db.go:389 that's a wrap engine=&{0xc0000edc80 0xc000490240 0xc000585c80 0xc00009de00 0xc00051e4c0 {160 +254724212224 root 128 0 false false : true} 0x9f6000 true Thank you for using Sarafu. Goodbye! false true 0} [T] postgresdb:pg.go:123 stop multi tx err= New session [D] atserver:parse.go:48 Received request: {"body":"channel=\u0026phoneNumber=%2B254724212224\u0026serviceCode=%2A483%2A061%23\u0026sessionId=DialogussSession__8294257475936592432\u0026text="}=?? [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, 127.0.0.1:7123).WithCancel.WithCancel sessionid '+254724212224', rootpath 'root', flagcount 128, language '' [] 0xc00054a000 false} [T] postgresdb:pg.go:93 begin single tx err= [D] engine:db.go:214 ca ca=&{0 0 [map[]] map[] false} [T] db:db.go:250 made db lookup key lk=102b323534373234323132323234, pfx=16 [T] postgresdb:pg.go:93 begin single tx err= [T] postgresdb:pg.go:176 get key=2b323534373234323132323234 [T] postgresdb:pg.go:113 stop single tx err= [I] persist:persist.go:126 loaded state and cache self=persister @0xc00051e4c0 state:0xc000534a00 cache:0xc000490240, key=+254724212224, state=state @0xc000534a00 moves: 24 idx: 0 flags: 0x0643100000000000000000000000000000 path: lang: eng (English) [T] persist:persist.go:127 loaded bytecode code= [T] engine:db.go:264 set persister st=state @0xc000534a00 moves: 24 idx: 0 flags: 0x0643100000000000000000000000000000 path: lang: eng (English), cac=&{0 0 [map[]] map[] false}, session=+254724212224, persister=persister @0xc00051e4c0 state:0xc000534a00 cache:0xc000490240 [I] vm:runner.go:63 vm created with state state=state @0xc000534a00 moves: 24 idx: 0 flags: 0x0643100000000000000000000000000000 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 @0xc000534a00 moves: 25 idx: 0 flags: 0x0643100000000000000000000000000000 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 @0xc000534a00 moves: 25 idx: 0 flags: 0x1043100000000000000000000000000000 path: _first lang: eng (English) [D] ussdmenuhandler:menuhandler.go:146 handler has been initialized state=state @0xc000534a00 moves: 25 idx: 0 flags: 0x1043100000000000000000000000000000 path: _first lang: eng (English), cache=&{0 0 [map[] map[]] map[] false}, x-SessionId=+254724212224 [D] cache:cache.go:72 Cache add key=_first, size=0, limit=0 [T] cache:cache.go:73 Cache add data value= [D] vm:runner.go:152 execute code opcode=7, op=HALT, code= [D] vm:runner.go:153 state=state @0xc000534a00 moves: 25 idx: 0 flags: 0x1043100000000000000000000000000000 path: _first lang: eng (English) [D] vm:runner.go:438 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:165 Cache free frame=1, key=_first, size=0 [D] state:state.go:346 code changed (set) code=000604726f6f74 [T] engine:db.go:605 reset on pristine state is a noop [I] engine:db.go:524 new VM execution with input input= [D] engine:db.go:533 start VM run code=000604726f6f74 [T] vm:runner.go:120 new vm run [D] vm:runner.go:152 execute code opcode=6, op=MOVE, code=04726f6f74 [D] vm:runner.go:153 state=state @0xc000534a00 moves: 26 idx: 0 flags: 0x1043100000000000000000000000000000 path: lang: eng (English) [T] resource:db.go:117 getcode sym=root [T] db:db.go:250 made db lookup key lk=01726f6f74, pfx=1 [T] fsdb:fs.go:108 fs get skip missing i=0 [T] fsdb:fs.go:108 fs get skip missing i=1 [T] fsdb:fs.go:111 trying fs get i=2, key=726f6f74, path=/var/www/html/golang/sarafu-vise/services/registration/1root [T] fsdb:fs.go:111 trying fs get i=3, key=726f6f74, path=/var/www/html/golang/sarafu-vise/services/registration/root.bin [D] vm:runner.go:363 loaded code sym=root, code=000314636865636b5f626c6f636b65645f7374617475730101000414636865636b5f626c6f636b65645f737461747573000315636865636b5f6163636f756e745f637265617465640102000415636865636b5f6163636f756e745f6372656174656400010e73656c665f72657365745f70696e01290100010f626c6f636b65645f6163636f756e7401260100010f73656c6563745f6c616e67756167650108000001057465726d7301090000010a6372656174655f70696e010e00000314636865636b5f6163636f756e745f7374617475730100000414636865636b5f6163636f756e745f73746174757300010b6170695f6661696c75726501190100010f6163636f756e745f70656e64696e67010b010001046d61696e010c010007 [D] vm:runner.go:152 execute code opcode=3, op=LOAD, code=14636865636b5f626c6f636b65645f7374617475730101000414636865636b5f626c6f636b65645f737461747573000315636865636b5f6163636f756e745f637265617465640102000415636865636b5f6163636f756e745f6372656174656400010e73656c665f72657365745f70696e01290100010f626c6f636b65645f6163636f756e7401260100010f73656c6563745f6c616e67756167650108000001057465726d7301090000010a6372656174655f70696e010e00000314636865636b5f6163636f756e745f7374617475730100000414636865636b5f6163636f756e745f73746174757300010b6170695f6661696c75726501190100010f6163636f756e745f70656e64696e67010b010001046d61696e010c010007 [D] vm:runner.go:153 state=state @0xc000534a00 moves: 27 idx: 0 flags: 0x1043100000000000000000000000000000 path: root lang: eng (English) [T] db:db.go:250 made db lookup key lk=202b3235343732343231323232342e0017, pfx=32 [T] postgresdb:pg.go:176 get key=0017 [I] postgresdb:pg.go:129 aborting tx tx=&{0xc0005a8090 0xc00047b998} [T] db:db.go:250 made db lookup key lk=202b3235343732343231323232342e0012, pfx=32 [T] postgresdb:pg.go:93 begin single tx err= [T] postgresdb:pg.go:176 get key=0012 [I] postgresdb:pg.go:129 aborting tx tx=&{0xc0005a8630 0xc00047b988} [D] cache:cache.go:72 Cache add key=check_blocked_status, size=0, limit=1 [T] cache:cache.go:73 Cache add data value= [D] vm:runner.go:152 execute code opcode=4, op=RELOAD, code=14636865636b5f626c6f636b65645f737461747573000315636865636b5f6163636f756e745f637265617465640102000415636865636b5f6163636f756e745f6372656174656400010e73656c665f72657365745f70696e01290100010f626c6f636b65645f6163636f756e7401260100010f73656c6563745f6c616e67756167650108000001057465726d7301090000010a6372656174655f70696e010e00000314636865636b5f6163636f756e745f7374617475730100000414636865636b5f6163636f756e745f73746174757300010b6170695f6661696c75726501190100010f6163636f756e745f70656e64696e67010b010001046d61696e010c010007 [D] vm:runner.go:153 state=state @0xc000534a00 moves: 27 idx: 0 flags: 0x1043100000000000000000000000000000 path: root lang: eng (English) [T] db:db.go:250 made db lookup key lk=202b3235343732343231323232342e0017, pfx=32 [T] postgresdb:pg.go:93 begin single tx err= [T] postgresdb:pg.go:176 get key=0017 [I] postgresdb:pg.go:129 aborting tx tx=&{0xc0005a8780 0xc00047b978} [T] db:db.go:250 made db lookup key lk=202b3235343732343231323232342e0012, pfx=32 [T] postgresdb:pg.go:93 begin single tx err= [T] postgresdb:pg.go:176 get key=0012 [I] postgresdb:pg.go:129 aborting tx tx=&{0xc0005a8870 0xc00047b968} [T] render:page.go:117 mapped key=check_blocked_status [D] vm:runner.go:152 execute code opcode=3, op=LOAD, code=15636865636b5f6163636f756e745f637265617465640102000415636865636b5f6163636f756e745f6372656174656400010e73656c665f72657365745f70696e01290100010f626c6f636b65645f6163636f756e7401260100010f73656c6563745f6c616e67756167650108000001057465726d7301090000010a6372656174655f70696e010e00000314636865636b5f6163636f756e745f7374617475730100000414636865636b5f6163636f756e745f73746174757300010b6170695f6661696c75726501190100010f6163636f756e745f70656e64696e67010b010001046d61696e010c010007 [D] vm:runner.go:153 state=state @0xc000534a00 moves: 27 idx: 0 flags: 0x1043100000000000000000000000000000 path: root lang: eng (English) [T] db:db.go:250 made db lookup key lk=202b3235343732343231323232342e0001, pfx=32 [T] postgresdb:pg.go:93 begin single tx err= [T] postgresdb:pg.go:176 get key=0001 [D] cache:cache.go:72 Cache add key=check_account_created, size=0, limit=2 [T] cache:cache.go:73 Cache add data value= [D] vm:runner.go:152 execute code opcode=4, op=RELOAD, code=15636865636b5f6163636f756e745f6372656174656400010e73656c665f72657365745f70696e01290100010f626c6f636b65645f6163636f756e7401260100010f73656c6563745f6c616e67756167650108000001057465726d7301090000010a6372656174655f70696e010e00000314636865636b5f6163636f756e745f7374617475730100000414636865636b5f6163636f756e745f73746174757300010b6170695f6661696c75726501190100010f6163636f756e745f70656e64696e67010b010001046d61696e010c010007 [D] vm:runner.go:153 state=state @0xc000534a00 moves: 27 idx: 0 flags: 0x1043100000000000000000000000000000 path: root lang: eng (English) [T] db:db.go:250 made db lookup key lk=202b3235343732343231323232342e0001, pfx=32 [T] postgresdb:pg.go:176 get key=0001 [T] render:page.go:117 mapped key=check_account_created [D] vm:runner.go:152 execute code opcode=1, op=CATCH, code=0e73656c665f72657365745f70696e01290100010f626c6f636b65645f6163636f756e7401260100010f73656c6563745f6c616e67756167650108000001057465726d7301090000010a6372656174655f70696e010e00000314636865636b5f6163636f756e745f7374617475730100000414636865636b5f6163636f756e745f73746174757300010b6170695f6661696c75726501190100010f6163636f756e745f70656e64696e67010b010001046d61696e010c010007 [D] vm:runner.go:153 state=state @0xc000534a00 moves: 27 idx: 0 flags: 0x1043100000000000000000000000000000 path: root lang: eng (English) [D] vm:runner.go:152 execute code opcode=1, op=CATCH, code=0f626c6f636b65645f6163636f756e7401260100010f73656c6563745f6c616e67756167650108000001057465726d7301090000010a6372656174655f70696e010e00000314636865636b5f6163636f756e745f7374617475730100000414636865636b5f6163636f756e745f73746174757300010b6170695f6661696c75726501190100010f6163636f756e745f70656e64696e67010b010001046d61696e010c010007 [D] vm:runner.go:153 state=state @0xc000534a00 moves: 27 idx: 0 flags: 0x1043100000000000000000000000000000 path: root lang: eng (English) [D] vm:runner.go:152 execute code opcode=1, op=CATCH, code=0f73656c6563745f6c616e67756167650108000001057465726d7301090000010a6372656174655f70696e010e00000314636865636b5f6163636f756e745f7374617475730100000414636865636b5f6163636f756e745f73746174757300010b6170695f6661696c75726501190100010f6163636f756e745f70656e64696e67010b010001046d61696e010c010007 [D] vm:runner.go:153 state=state @0xc000534a00 moves: 27 idx: 0 flags: 0x1043100000000000000000000000000000 path: root lang: eng (English) [D] vm:runner.go:152 execute code opcode=1, op=CATCH, code=057465726d7301090000010a6372656174655f70696e010e00000314636865636b5f6163636f756e745f7374617475730100000414636865636b5f6163636f756e745f73746174757300010b6170695f6661696c75726501190100010f6163636f756e745f70656e64696e67010b010001046d61696e010c010007 [D] vm:runner.go:153 state=state @0xc000534a00 moves: 27 idx: 0 flags: 0x1043100000000000000000000000000000 path: root lang: eng (English) [D] vm:runner.go:152 execute code opcode=1, op=CATCH, code=0a6372656174655f70696e010e00000314636865636b5f6163636f756e745f7374617475730100000414636865636b5f6163636f756e745f73746174757300010b6170695f6661696c75726501190100010f6163636f756e745f70656e64696e67010b010001046d61696e010c010007 [D] vm:runner.go:153 state=state @0xc000534a00 moves: 27 idx: 0 flags: 0x1043100000000000000000000000000000 path: root lang: eng (English) [D] vm:runner.go:152 execute code opcode=3, op=LOAD, code=14636865636b5f6163636f756e745f7374617475730100000414636865636b5f6163636f756e745f73746174757300010b6170695f6661696c75726501190100010f6163636f756e745f70656e64696e67010b010001046d61696e010c010007 [D] vm:runner.go:153 state=state @0xc000534a00 moves: 27 idx: 0 flags: 0x1043100000000000000000000000000000 path: root lang: eng (English) [T] db:db.go:250 made db lookup key lk=202b3235343732343231323232342e0001, pfx=32 [T] postgresdb:pg.go:176 get key=0001 2025/04/25 13:33:08 URL: http://localhost:5003/api/v2/account/status/0xB1dB36f224026010fBD7056abAe4bD29203f46Fe | Content-Type: application/json | Method: GET| Request Body: - 2025/04/25 13:33:08 Received response for http://localhost:5003/api/v2/account/status/0xB1dB36f224026010fBD7056abAe4bD29203f46Fe: Status Code: 200 | Content-Type: application/json [D] cache:cache.go:72 Cache add key=check_account_status, size=0, limit=0 [T] cache:cache.go:73 Cache add data value= [D] vm:runner.go:152 execute code opcode=4, op=RELOAD, code=14636865636b5f6163636f756e745f73746174757300010b6170695f6661696c75726501190100010f6163636f756e745f70656e64696e67010b010001046d61696e010c010007 [D] vm:runner.go:153 state=state @0xc000534a00 moves: 27 idx: 0 flags: 0x1053100000000000000000000000000000 path: root lang: eng (English) [T] db:db.go:250 made db lookup key lk=202b3235343732343231323232342e0001, pfx=32 [T] postgresdb:pg.go:176 get key=0001 2025/04/25 13:33:08 URL: http://localhost:5003/api/v2/account/status/0xB1dB36f224026010fBD7056abAe4bD29203f46Fe | Content-Type: application/json | Method: GET| Request Body: - 2025/04/25 13:33:08 Received response for http://localhost:5003/api/v2/account/status/0xB1dB36f224026010fBD7056abAe4bD29203f46Fe: Status Code: 200 | Content-Type: application/json [T] render:page.go:117 mapped key=check_account_status [D] vm:runner.go:152 execute code opcode=1, op=CATCH, code=0b6170695f6661696c75726501190100010f6163636f756e745f70656e64696e67010b010001046d61696e010c010007 [D] vm:runner.go:153 state=state @0xc000534a00 moves: 27 idx: 0 flags: 0x1053100000000000000000000000000000 path: root lang: eng (English) [D] vm:runner.go:152 execute code opcode=1, op=CATCH, code=0f6163636f756e745f70656e64696e67010b010001046d61696e010c010007 [D] vm:runner.go:153 state=state @0xc000534a00 moves: 27 idx: 0 flags: 0x1053100000000000000000000000000000 path: root lang: eng (English) [D] vm:runner.go:152 execute code opcode=1, op=CATCH, code=046d61696e010c010007 [D] vm:runner.go:153 state=state @0xc000534a00 moves: 27 idx: 0 flags: 0x1053100000000000000000000000000000 path: root lang: eng (English) [I] vm:runner.go:276 catch! flag=12, sym=main, target=main, mode=true [T] resource:db.go:117 getcode sym=main [T] db:db.go:250 made db lookup key lk=016d61696e, pfx=1 [T] fsdb:fs.go:108 fs get skip missing i=0 [T] fsdb:fs.go:108 fs get skip missing i=1 [T] fsdb:fs.go:111 trying fs get i=2, key=6d61696e, path=/var/www/html/golang/sarafu-vise/services/registration/1main [T] fsdb:fs.go:111 trying fs get i=3, key=6d61696e, path=/var/www/html/golang/sarafu-vise/services/registration/main.bin [D] vm:runner.go:152 execute code opcode=3, op=LOAD, code=15636c6561725f74656d706f726172795f76616c75650102000415636c6561725f74656d706f726172795f76616c756500030f6d616e6167655f766f75636865727301a000040f6d616e6167655f766f75636865727300030d636865636b5f62616c616e6365018000040d636865636b5f62616c616e636500010b6170695f6661696c75726501190100050d636865636b5f62616c616e6365000a0473656e640131000a08766f7563686572730132000a076163636f756e740133000a0468656c700134000a04717569740139000700080473656e64013100080b6d795f766f756368657273013200080a6d795f6163636f756e74013300080468656c7001340008047175697401390008012e012a [D] vm:runner.go:153 state=state @0xc000534a00 moves: 28 idx: 0 flags: 0x1053100000000000000000000000000000 path: root/main lang: eng (English) running ClearTemporaryValue [T] db:db.go:250 made db lookup key lk=202b3235343732343231323232342e000b, pfx=32 [T] postgresdb:pg.go:149 put key=000b, val= [D] cache:cache.go:72 Cache add key=clear_temporary_value, size=0, limit=2 [T] cache:cache.go:73 Cache add data value= [D] vm:runner.go:152 execute code opcode=4, op=RELOAD, code=15636c6561725f74656d706f726172795f76616c756500030f6d616e6167655f766f75636865727301a000040f6d616e6167655f766f75636865727300030d636865636b5f62616c616e6365018000040d636865636b5f62616c616e636500010b6170695f6661696c75726501190100050d636865636b5f62616c616e6365000a0473656e640131000a08766f7563686572730132000a076163636f756e740133000a0468656c700134000a04717569740139000700080473656e64013100080b6d795f766f756368657273013200080a6d795f6163636f756e74013300080468656c7001340008047175697401390008012e012a [D] vm:runner.go:153 state=state @0xc000534a00 moves: 28 idx: 0 flags: 0x1053100000000000000000000000000000 path: root/main lang: eng (English) running ClearTemporaryValue [T] db:db.go:250 made db lookup key lk=202b3235343732343231323232342e000b, pfx=32 [T] postgresdb:pg.go:149 put key=000b, val= [T] render:page.go:117 mapped key=clear_temporary_value [D] vm:runner.go:152 execute code opcode=3, op=LOAD, code=0f6d616e6167655f766f75636865727301a000040f6d616e6167655f766f75636865727300030d636865636b5f62616c616e6365018000040d636865636b5f62616c616e636500010b6170695f6661696c75726501190100050d636865636b5f62616c616e6365000a0473656e640131000a08766f7563686572730132000a076163636f756e740133000a0468656c700134000a04717569740139000700080473656e64013100080b6d795f766f756368657273013200080a6d795f6163636f756e74013300080468656c7001340008047175697401390008012e012a [D] vm:runner.go:153 state=state @0xc000534a00 moves: 28 idx: 0 flags: 0x1053100000000000000000000000000000 path: root/main lang: eng (English) [T] db:db.go:250 made db lookup key lk=202b3235343732343231323232342e0001, pfx=32 [T] postgresdb:pg.go:176 get key=0001 [T] db:db.go:250 made db lookup key lk=202b3235343732343231323232342e000c, pfx=32 [T] postgresdb:pg.go:176 get key=000c [I] postgresdb:pg.go:129 aborting tx tx=&{0xc0005a89c0 0xc00047b958} [T] db:db.go:250 made db lookup key lk=202b3235343732343231323232342e000d, pfx=32 [T] postgresdb:pg.go:93 begin single tx err= [T] postgresdb:pg.go:149 put key=000d, val=3130 [T] db:db.go:250 made db lookup key lk=202b3235343732343231323232342e0010, pfx=32 [T] postgresdb:pg.go:149 put key=0010, val=36 [T] db:db.go:250 made db lookup key lk=202b3235343732343231323232342e0011, pfx=32 [T] postgresdb:pg.go:149 put key=0011, val=307863423435334237343242633842453142416130334365313932376532383737383864306146303635 [T] db:db.go:250 made db lookup key lk=202b3235343732343231323232342e000c, pfx=32 [T] postgresdb:pg.go:149 put key=000c, val=504553 [I] ussdmenuhandler:menuhandler.go:1983 Default voucher set symbol=PES, balance=10000000, decimals=6, address=0xcB453B742Bc8BE1BAa03Ce1927e287788d0aF065, x-SessionId=+254724212224 [T] db:db.go:250 made db lookup key lk=202b3235343732343231323232342e0101, pfx=32 [T] postgresdb:pg.go:149 put key=0101, val=313a3130 [T] db:db.go:250 made db lookup key lk=202b3235343732343231323232342e0102, pfx=32 [T] postgresdb:pg.go:149 put key=0102, val=313a36 [T] db:db.go:250 made db lookup key lk=202b3235343732343231323232342e0103, pfx=32 [T] postgresdb:pg.go:149 put key=0103, val=313a307863423435334237343242633842453142416130334365313932376532383737383864306146303635 [T] db:db.go:250 made db lookup key lk=202b3235343732343231323232342e0100, pfx=32 [T] postgresdb:pg.go:149 put key=0100, val=313a504553 [D] cache:cache.go:72 Cache add key=manage_vouchers, size=0, limit=160 [T] cache:cache.go:73 Cache add data value= [D] vm:runner.go:152 execute code opcode=4, op=RELOAD, code=0f6d616e6167655f766f75636865727300030d636865636b5f62616c616e6365018000040d636865636b5f62616c616e636500010b6170695f6661696c75726501190100050d636865636b5f62616c616e6365000a0473656e640131000a08766f7563686572730132000a076163636f756e740133000a0468656c700134000a04717569740139000700080473656e64013100080b6d795f766f756368657273013200080a6d795f6163636f756e74013300080468656c7001340008047175697401390008012e012a [D] vm:runner.go:153 state=state @0xc000534a00 moves: 28 idx: 0 flags: 0x1053100000000000000000000000000000 path: root/main lang: eng (English) [T] db:db.go:250 made db lookup key lk=202b3235343732343231323232342e0001, pfx=32 [T] postgresdb:pg.go:176 get key=0001 [T] db:db.go:250 made db lookup key lk=202b3235343732343231323232342e000c, pfx=32 [T] postgresdb:pg.go:176 get key=000c [T] vouchers:vouchers.go:167 dtal data=&{0xcB453B742Bc8BE1BAa03Ce1927e287788d0aF065 PES 6 10}, x-SessionId=+254724212224 [T] db:db.go:250 made db lookup key lk=202b3235343732343231323232342e0011, pfx=32 [T] postgresdb:pg.go:149 put key=0011, val=307863423435334237343242633842453142416130334365313932376532383737383864306146303635 [T] db:db.go:250 made db lookup key lk=202b3235343732343231323232342e000c, pfx=32 [T] postgresdb:pg.go:149 put key=000c, val=504553 [T] db:db.go:250 made db lookup key lk=202b3235343732343231323232342e000d, pfx=32 [T] postgresdb:pg.go:149 put key=000d, val=3130 [T] db:db.go:250 made db lookup key lk=202b3235343732343231323232342e0010, pfx=32 [T] postgresdb:pg.go:149 put key=0010, val=36 [T] db:db.go:250 made db lookup key lk=202b3235343732343231323232342e0100, pfx=32 [T] postgresdb:pg.go:149 put key=0100, val=313a504553 [T] db:db.go:250 made db lookup key lk=202b3235343732343231323232342e0101, pfx=32 [T] postgresdb:pg.go:149 put key=0101, val=313a3130 [T] db:db.go:250 made db lookup key lk=202b3235343732343231323232342e0102, pfx=32 [T] postgresdb:pg.go:149 put key=0102, val=313a36 [T] db:db.go:250 made db lookup key lk=202b3235343732343231323232342e0103, pfx=32 [T] postgresdb:pg.go:149 put key=0103, val=313a307863423435334237343242633842453142416130334365313932376532383737383864306146303635 [T] render:page.go:117 mapped key=manage_vouchers [D] vm:runner.go:152 execute code opcode=3, op=LOAD, code=0d636865636b5f62616c616e6365018000040d636865636b5f62616c616e636500010b6170695f6661696c75726501190100050d636865636b5f62616c616e6365000a0473656e640131000a08766f7563686572730132000a076163636f756e740133000a0468656c700134000a04717569740139000700080473656e64013100080b6d795f766f756368657273013200080a6d795f6163636f756e74013300080468656c7001340008047175697401390008012e012a [D] vm:runner.go:153 state=state @0xc000534a00 moves: 28 idx: 0 flags: 0x1053100000000000000000000000000000 path: root/main lang: eng (English) [T] db:db.go:250 made db lookup key lk=202b3235343732343231323232342e000c, pfx=32 [T] postgresdb:pg.go:176 get key=000c [T] db:db.go:250 made db lookup key lk=202b3235343732343231323232342e000d, pfx=32 [T] postgresdb:pg.go:176 get key=000d [T] db:db.go:250 made db lookup key lk=202b3235343732343231323232342e0015, pfx=32 [T] postgresdb:pg.go:176 get key=0015 [D] cache:cache.go:72 Cache add key=check_balance, size=19, limit=128 [T] cache:cache.go:73 Cache add data value=Balance: 10.00 PES [D] vm:runner.go:152 execute code opcode=4, op=RELOAD, code=0d636865636b5f62616c616e636500010b6170695f6661696c75726501190100050d636865636b5f62616c616e6365000a0473656e640131000a08766f7563686572730132000a076163636f756e740133000a0468656c700134000a04717569740139000700080473656e64013100080b6d795f766f756368657273013200080a6d795f6163636f756e74013300080468656c7001340008047175697401390008012e012a [D] vm:runner.go:153 state=state @0xc000534a00 moves: 28 idx: 0 flags: 0x1053100000000000000000000000000000 path: root/main lang: eng (English) [T] db:db.go:250 made db lookup key lk=202b3235343732343231323232342e000c, pfx=32 [T] postgresdb:pg.go:176 get key=000c [T] db:db.go:250 made db lookup key lk=202b3235343732343231323232342e000d, pfx=32 [T] postgresdb:pg.go:176 get key=000d [T] db:db.go:250 made db lookup key lk=202b3235343732343231323232342e0015, pfx=32 [T] postgresdb:pg.go:176 get key=0015 [T] render:page.go:117 mapped key=check_balance [D] vm:runner.go:152 execute code opcode=1, op=CATCH, code=0b6170695f6661696c75726501190100050d636865636b5f62616c616e6365000a0473656e640131000a08766f7563686572730132000a076163636f756e740133000a0468656c700134000a04717569740139000700080473656e64013100080b6d795f766f756368657273013200080a6d795f6163636f756e74013300080468656c7001340008047175697401390008012e012a [D] vm:runner.go:153 state=state @0xc000534a00 moves: 28 idx: 0 flags: 0x1053100000000000000000000000000000 path: root/main lang: eng (English) [D] vm:runner.go:152 execute code opcode=5, op=MAP, code=0d636865636b5f62616c616e6365000a0473656e640131000a08766f7563686572730132000a076163636f756e740133000a0468656c700134000a04717569740139000700080473656e64013100080b6d795f766f756368657273013200080a6d795f6163636f756e74013300080468656c7001340008047175697401390008012e012a [D] vm:runner.go:153 state=state @0xc000534a00 moves: 28 idx: 0 flags: 0x1053100000000000000000000000000000 path: root/main lang: eng (English) [T] render:page.go:117 mapped key=check_balance [D] vm:runner.go:152 execute code opcode=10, op=MOUT, code=0473656e640131000a08766f7563686572730132000a076163636f756e740133000a0468656c700134000a04717569740139000700080473656e64013100080b6d795f766f756368657273013200080a6d795f6163636f756e74013300080468656c7001340008047175697401390008012e012a [D] vm:runner.go:153 state=state @0xc000534a00 moves: 28 idx: 0 flags: 0x1053100000000000000000000000000000 path: root/main lang: eng (English) [D] vm:runner.go:152 execute code opcode=10, op=MOUT, code=08766f7563686572730132000a076163636f756e740133000a0468656c700134000a04717569740139000700080473656e64013100080b6d795f766f756368657273013200080a6d795f6163636f756e74013300080468656c7001340008047175697401390008012e012a [D] vm:runner.go:153 state=state @0xc000534a00 moves: 28 idx: 0 flags: 0x1053100000000000000000000000000000 path: root/main lang: eng (English) [D] vm:runner.go:152 execute code opcode=10, op=MOUT, code=076163636f756e740133000a0468656c700134000a04717569740139000700080473656e64013100080b6d795f766f756368657273013200080a6d795f6163636f756e74013300080468656c7001340008047175697401390008012e012a [D] vm:runner.go:153 state=state @0xc000534a00 moves: 28 idx: 0 flags: 0x1053100000000000000000000000000000 path: root/main lang: eng (English) [D] vm:runner.go:152 execute code opcode=10, op=MOUT, code=0468656c700134000a04717569740139000700080473656e64013100080b6d795f766f756368657273013200080a6d795f6163636f756e74013300080468656c7001340008047175697401390008012e012a [D] vm:runner.go:153 state=state @0xc000534a00 moves: 28 idx: 0 flags: 0x1053100000000000000000000000000000 path: root/main lang: eng (English) [D] vm:runner.go:152 execute code opcode=10, op=MOUT, code=04717569740139000700080473656e64013100080b6d795f766f756368657273013200080a6d795f6163636f756e74013300080468656c7001340008047175697401390008012e012a [D] vm:runner.go:153 state=state @0xc000534a00 moves: 28 idx: 0 flags: 0x1053100000000000000000000000000000 path: root/main lang: eng (English) [D] vm:runner.go:152 execute code opcode=7, op=HALT, code=00080473656e64013100080b6d795f766f756368657273013200080a6d795f6163636f756e74013300080468656c7001340008047175697401390008012e012a [D] vm:runner.go:153 state=state @0xc000534a00 moves: 28 idx: 0 flags: 0x1053100000000000000000000000000000 path: root/main lang: eng (English) [D] vm:runner.go:438 found HALT, stopping [D] engine:db.go:540 end VM run code=00080473656e64013100080b6d795f766f756368657273013200080a6d795f6163636f756e74013300080468656c7001340008047175697401390008012e012a, state=state @0xc000534a00 moves: 28 idx: 0 flags: 0x1453100000000000000000000000000000 path: root/main lang: eng (English), vm=vm (0xc0005d61e0) ok [D] state:state.go:346 code changed (set) code=00080473656e64013100080b6d795f766f756368657273013200080a6d795f6163636f756e74013300080468656c7001340008047175697401390008012e012a [T] engine:db.go:572 render with state state=state @0xc000534a00 moves: 28 idx: 0 flags: 0x1453100000000000000000000000000000 path: root/main lang: eng (English) [I] render:page.go:234 found sink sym=main, sink=check_account_status [D] render:size.go:87 Added cursor offset=0 [T] db:db.go:245 language using ln=eng (English) [T] db:db.go:250 made db lookup key lk=046d61696e, pfx=4 [T] fsdb:fs.go:111 trying fs get i=0, key=6d61696e, path=/var/www/html/golang/sarafu-vise/services/registration/4main_eng [T] fsdb:fs.go:111 trying fs get i=1, key=6d61696e, path=/var/www/html/golang/sarafu-vise/services/registration/main_eng [T] fsdb:fs.go:111 trying fs get i=2, key=6d61696e, path=/var/www/html/golang/sarafu-vise/services/registration/4main [T] fsdb:fs.go:111 trying fs get i=3, key=6d61696e, path=/var/www/html/golang/sarafu-vise/services/registration/main [T] render:size.go:100 check values k=clear_temporary_value, v=, idx=0, cursors=[0] [T] render:size.go:100 check values k=manage_vouchers, v=, idx=0, cursors=[0] [T] render:size.go:100 check values k=check_balance, v=Balance: 10.00 PES , idx=0, cursors=[0] [T] render:size.go:100 check values k=check_blocked_status, v=, idx=0, cursors=[0] [T] render:size.go:100 check values k=check_account_created, v=, idx=0, cursors=[0] [T] render:size.go:100 check values k=check_account_status, v=, idx=0, cursors=[0] [D] render:page.go:175 render for index=0 [D] render:page.go:391 rendered template bytes=19 [T] db:db.go:245 language using ln=eng (English) [T] db:db.go:250 made db lookup key lk=0273656e645f6d656e75, pfx=2 [T] fsdb:fs.go:111 trying fs get i=0, key=73656e645f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/2send_menu_eng [T] fsdb:fs.go:111 trying fs get i=1, key=73656e645f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/send_menu_eng [T] fsdb:fs.go:111 trying fs get i=2, key=73656e645f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/2send_menu [T] fsdb:fs.go:111 trying fs get i=3, key=73656e645f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/send_menu [T] db:db.go:245 language using ln=eng (English) [T] db:db.go:250 made db lookup key lk=02766f7563686572735f6d656e75, pfx=2 [T] fsdb:fs.go:111 trying fs get i=0, key=766f7563686572735f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/2vouchers_menu_eng [T] fsdb:fs.go:111 trying fs get i=1, key=766f7563686572735f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/vouchers_menu_eng [T] fsdb:fs.go:111 trying fs get i=2, key=766f7563686572735f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/2vouchers_menu [T] fsdb:fs.go:111 trying fs get i=3, key=766f7563686572735f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/vouchers_menu [T] db:db.go:245 language using ln=eng (English) [T] db:db.go:250 made db lookup key lk=026163636f756e745f6d656e75, pfx=2 [T] fsdb:fs.go:111 trying fs get i=0, key=6163636f756e745f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/2account_menu_eng [T] fsdb:fs.go:111 trying fs get i=1, key=6163636f756e745f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/account_menu_eng [T] fsdb:fs.go:111 trying fs get i=2, key=6163636f756e745f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/2account_menu [T] fsdb:fs.go:111 trying fs get i=3, key=6163636f756e745f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/account_menu [T] db:db.go:245 language using ln=eng (English) [T] db:db.go:250 made db lookup key lk=0268656c705f6d656e75, pfx=2 [T] fsdb:fs.go:111 trying fs get i=0, key=68656c705f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/2help_menu_eng [T] fsdb:fs.go:111 trying fs get i=1, key=68656c705f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/help_menu_eng [T] fsdb:fs.go:111 trying fs get i=2, key=68656c705f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/2help_menu [T] fsdb:fs.go:111 trying fs get i=3, key=68656c705f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/help_menu [T] db:db.go:245 language using ln=eng (English) [T] db:db.go:250 made db lookup key lk=02717569745f6d656e75, pfx=2 [T] fsdb:fs.go:111 trying fs get i=0, key=717569745f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/2quit_menu_eng [T] fsdb:fs.go:111 trying fs get i=1, key=717569745f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/quit_menu_eng [T] fsdb:fs.go:111 trying fs get i=2, key=717569745f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/2quit_menu [T] fsdb:fs.go:111 trying fs get i=3, key=717569745f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/quit_menu [D] render:page.go:400 rendered menu bytes=52 [D] render:menu.go:261 applypage m=pagecount: 2 menusink: false next: false prev: false, idx=0 [D] render:menu.go:261 applypage m=pagecount: 2 menusink: false next: false prev: false, idx=1 [D] render:page.go:361 calculated pre-navigation allocation bytes=88, menusizes=[0 0 0 0] [T] render:page.go:267 processing sink idx=0, value=, netremaining=87, l=0 [T] render:page.go:377 nosinkvalue idx=0, value= [T] db:db.go:245 language using ln=eng (English) [T] db:db.go:250 made db lookup key lk=046d61696e, pfx=4 [T] fsdb:fs.go:111 trying fs get i=0, key=6d61696e, path=/var/www/html/golang/sarafu-vise/services/registration/4main_eng [T] fsdb:fs.go:111 trying fs get i=1, key=6d61696e, path=/var/www/html/golang/sarafu-vise/services/registration/main_eng [T] fsdb:fs.go:111 trying fs get i=2, key=6d61696e, path=/var/www/html/golang/sarafu-vise/services/registration/4main [T] fsdb:fs.go:111 trying fs get i=3, key=6d61696e, path=/var/www/html/golang/sarafu-vise/services/registration/main [T] render:size.go:100 check values k=manage_vouchers, v=, idx=0, cursors=[0] [T] render:size.go:100 check values k=check_balance, v=Balance: 10.00 PES , idx=0, cursors=[0] [T] render:size.go:100 check values k=check_blocked_status, v=, idx=0, cursors=[0] [T] render:size.go:100 check values k=check_account_created, v=, idx=0, cursors=[0] [T] render:size.go:100 check values k=check_account_status, v=, idx=0, cursors=[0] [T] render:size.go:100 check values k=clear_temporary_value, v=, idx=0, cursors=[0] [D] render:page.go:175 render for index=0 [D] render:page.go:391 rendered template bytes=19 [T] db:db.go:245 language using ln=eng (English) [T] db:db.go:250 made db lookup key lk=0273656e645f6d656e75, pfx=2 [T] fsdb:fs.go:111 trying fs get i=0, key=73656e645f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/2send_menu_eng [T] fsdb:fs.go:111 trying fs get i=1, key=73656e645f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/send_menu_eng [T] fsdb:fs.go:111 trying fs get i=2, key=73656e645f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/2send_menu [T] fsdb:fs.go:111 trying fs get i=3, key=73656e645f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/send_menu [T] db:db.go:245 language using ln=eng (English) [T] db:db.go:250 made db lookup key lk=02766f7563686572735f6d656e75, pfx=2 [T] fsdb:fs.go:111 trying fs get i=0, key=766f7563686572735f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/2vouchers_menu_eng [T] fsdb:fs.go:111 trying fs get i=1, key=766f7563686572735f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/vouchers_menu_eng [T] fsdb:fs.go:111 trying fs get i=2, key=766f7563686572735f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/2vouchers_menu [T] fsdb:fs.go:111 trying fs get i=3, key=766f7563686572735f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/vouchers_menu [T] db:db.go:245 language using ln=eng (English) [T] db:db.go:250 made db lookup key lk=026163636f756e745f6d656e75, pfx=2 [T] fsdb:fs.go:111 trying fs get i=0, key=6163636f756e745f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/2account_menu_eng [T] fsdb:fs.go:111 trying fs get i=1, key=6163636f756e745f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/account_menu_eng [T] fsdb:fs.go:111 trying fs get i=2, key=6163636f756e745f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/2account_menu [T] fsdb:fs.go:111 trying fs get i=3, key=6163636f756e745f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/account_menu [T] db:db.go:245 language using ln=eng (English) [T] db:db.go:250 made db lookup key lk=0268656c705f6d656e75, pfx=2 [T] fsdb:fs.go:111 trying fs get i=0, key=68656c705f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/2help_menu_eng [T] fsdb:fs.go:111 trying fs get i=1, key=68656c705f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/help_menu_eng [T] fsdb:fs.go:111 trying fs get i=2, key=68656c705f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/2help_menu [T] fsdb:fs.go:111 trying fs get i=3, key=68656c705f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/help_menu [T] db:db.go:245 language using ln=eng (English) [T] db:db.go:250 made db lookup key lk=02717569745f6d656e75, pfx=2 [T] fsdb:fs.go:111 trying fs get i=0, key=717569745f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/2quit_menu_eng [T] fsdb:fs.go:111 trying fs get i=1, key=717569745f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/quit_menu_eng [T] fsdb:fs.go:111 trying fs get i=2, key=717569745f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/2quit_menu [T] fsdb:fs.go:111 trying fs get i=3, key=717569745f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/quit_menu [D] render:page.go:400 rendered menu bytes=52 [I] persist:persist.go:100 saving state and cache self=persister @0xc00051e4c0 state:0xc000534a00 cache:0xc000490240, key=+254724212224, state=state @0xc000534a00 moves: 28 idx: 0 flags: 0x0453100000000000000000000000000000 path: root/main lang: eng (English) [T] persist:persist.go:101 saving bytecode code=00080473656e64013100080b6d795f766f756368657273013200080a6d795f6163636f756e74013300080468656c7001340008047175697401390008012e012a [T] db:db.go:250 made db lookup key lk=102b323534373234323132323234, pfx=16 [T] postgresdb:pg.go:93 begin single tx err= [T] postgresdb:pg.go:149 put key=2b323534373234323132323234, val=a2655374617465a764436f6465584000080473656e64013100080b6d795f766f756368657273013200080a6d795f6163636f756e74013300080468656c7001340008047175697401390008012e012a6845786563506174688264726f6f74646d61696e6742697453697a6518886753697a654964780065466c616773510453100000000000000000000000000000654d6f766573181c684c616e6775616765a264436f646563656e67644e616d6567456e676c697368664d656d6f7279a569436163686553697a65006c436163686555736553697a651365436163686583a0a374636865636b5f626c6f636b65645f7374617475736075636865636b5f6163636f756e745f637265617465646074636865636b5f6163636f756e745f73746174757360a375636c6561725f74656d706f726172795f76616c7565606f6d616e6167655f766f756368657273606d636865636b5f62616c616e63657342616c616e63653a2031302e3030205045530a6553697a6573a66d636865636b5f62616c616e6365188074636865636b5f626c6f636b65645f7374617475730175636865636b5f6163636f756e745f637265617465640274636865636b5f6163636f756e745f7374617475730075636c6561725f74656d706f726172795f76616c7565026f6d616e6167655f766f75636865727318a0694c61737456616c75657342616c616e63653a2031302e3030205045530a [T] postgresdb:pg.go:113 stop single tx err= [T] persist:persist.go:107 state and cache flushed from persister [T] engine:db.go:389 that's a wrap engine=&{0xc000534a00 0xc000490240 0xc0005d61e0 0xc00009de00 0xc00051e4c0 {160 +254724212224 root 128 0 false false : true} 0x9f6000 true false true 0} [T] postgresdb:pg.go:123 stop multi tx err= ===== Send node ======= [D] atserver:parse.go:48 Received request: {"body":"channel=\u0026phoneNumber=%2B254724212224\u0026serviceCode=%2A483%2A061%23\u0026sessionId=DialogussSession__8294257475936592432\u0026text=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, 127.0.0.1:7123).WithCancel.WithCancel sessionid '+254724212224', rootpath 'root', flagcount 128, language '' [49] 0xc00054a000 false} [T] postgresdb:pg.go:93 begin single tx err= [D] engine:db.go:214 ca ca=&{0 0 [map[]] map[check_account_created:2 check_account_status:0 check_balance:128 check_blocked_status:1 clear_temporary_value:2 manage_vouchers:160] Balance: 10.00 PES false} [T] db:db.go:250 made db lookup key lk=102b323534373234323132323234, pfx=16 [T] postgresdb:pg.go:93 begin single tx err= [T] postgresdb:pg.go:176 get key=2b323534373234323132323234 [T] postgresdb:pg.go:113 stop single tx err= [I] persist:persist.go:126 loaded state and cache self=persister @0xc00051e4c0 state:0xc000534300 cache:0xc000490240, key=+254724212224, state=state @0xc000534300 moves: 28 idx: 0 flags: 0x0453100000000000000000000000000000 path: root/main lang: eng (English) [T] persist:persist.go:127 loaded bytecode code=00080473656e64013100080b6d795f766f756368657273013200080a6d795f6163636f756e74013300080468656c7001340008047175697401390008012e012a [T] engine:db.go:264 set persister st=state @0xc000534300 moves: 28 idx: 0 flags: 0x0453100000000000000000000000000000 path: root/main lang: eng (English), cac=&{0 19 [map[] map[check_account_created: check_account_status: check_blocked_status:] map[check_balance:Balance: 10.00 PES clear_temporary_value: manage_vouchers:]] map[check_account_created:2 check_account_status:0 check_balance:128 check_blocked_status:1 clear_temporary_value:2 manage_vouchers:160] Balance: 10.00 PES false}, session=+254724212224, persister=persister @0xc00051e4c0 state:0xc000534300 cache:0xc000490240 [I] vm:runner.go:63 vm created with state state=state @0xc000534300 moves: 28 idx: 0 flags: 0x0453100000000000000000000000000000 path: root/main 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 @0xc000534300 moves: 29 idx: 0 flags: 0x0453100000000000000000000000000000 path: root/main/_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 @0xc000534300 moves: 29 idx: 0 flags: 0x1053100000000000000000000000000000 path: root/main/_first lang: eng (English) [D] ussdmenuhandler:menuhandler.go:146 handler has been initialized state=state @0xc000534300 moves: 29 idx: 0 flags: 0x1053100000000000000000000000000000 path: root/main/_first lang: eng (English), cache=&{0 19 [map[] map[check_account_created: check_account_status: check_blocked_status:] map[check_balance:Balance: 10.00 PES clear_temporary_value: manage_vouchers:] map[]] map[check_account_created:2 check_account_status:0 check_balance:128 check_blocked_status:1 clear_temporary_value:2 manage_vouchers:160] Balance: 10.00 PES false}, x-SessionId=+254724212224 [D] cache:cache.go:72 Cache add key=_first, size=0, limit=0 [T] cache:cache.go:73 Cache add data value= [D] vm:runner.go:152 execute code opcode=7, op=HALT, code= [D] vm:runner.go:153 state=state @0xc000534300 moves: 29 idx: 0 flags: 0x1053100000000000000000000000000000 path: root/main/_first lang: eng (English) [D] vm:runner.go:438 found HALT, stopping [D] engine:db.go:361 end pre-VM check [T] state:state.go:319 execpath before path=[root main _first] [T] state:state.go:326 execpath after path=[root main] [D] cache:cache.go:165 Cache free frame=3, key=_first, size=0 [I] engine:db.go:524 new VM execution with input input=31 [D] engine:db.go:533 start VM run code=00080473656e64013100080b6d795f766f756368657273013200080a6d795f6163636f756e74013300080468656c7001340008047175697401390008012e012a [T] vm:runner.go:120 new vm run [D] vm:runner.go:152 execute code opcode=8, op=INCMP, code=0473656e64013100080b6d795f766f756368657273013200080a6d795f6163636f756e74013300080468656c7001340008047175697401390008012e012a [D] vm:runner.go:153 state=state @0xc000534300 moves: 30 idx: 0 flags: 0x1053100000000000000000000000000000 path: root/main lang: eng (English) [T] vm:runner.go:394 testing sym sym=send, input=31 [I] vm:runner.go:402 input match input=31, next=send [T] resource:db.go:117 getcode sym=send [T] db:db.go:250 made db lookup key lk=0173656e64, pfx=1 [T] fsdb:fs.go:108 fs get skip missing i=0 [T] fsdb:fs.go:108 fs get skip missing i=1 [T] fsdb:fs.go:111 trying fs get i=2, key=73656e64, path=/var/www/html/golang/sarafu-vise/services/registration/1send [T] fsdb:fs.go:111 trying fs get i=3, key=73656e64, path=/var/www/html/golang/sarafu-vise/services/registration/send.bin [D] vm:runner.go:426 loaded additional code next=send, code=0003117472616e73616374696f6e5f726573657401000004117472616e73616374696f6e5f726573657400010a6e6f5f766f7563686572011a01000a046261636b0130000700031276616c69646174655f726563697069656e74013200041276616c69646174655f726563697069656e74000111696e76616c69645f726563697069656e74011001000110696e766974655f726563697069656e740111010008015f0130000806616d6f756e74012a [D] vm:runner.go:152 execute code opcode=8, op=INCMP, code=0b6d795f766f756368657273013200080a6d795f6163636f756e74013300080468656c7001340008047175697401390008012e012a0003117472616e73616374696f6e5f726573657401000004117472616e73616374696f6e5f726573657400010a6e6f5f766f7563686572011a01000a046261636b0130000700031276616c69646174655f726563697069656e74013200041276616c69646174655f726563697069656e74000111696e76616c69645f726563697069656e74011001000110696e766974655f726563697069656e740111010008015f0130000806616d6f756e74012a [D] vm:runner.go:153 state=state @0xc000534300 moves: 31 idx: 0 flags: 0x1253100000000000000000000000000000 path: root/main/send lang: eng (English) [T] vm:runner.go:394 testing sym sym=my_vouchers, input=31 [D] vm:runner.go:152 execute code opcode=8, op=INCMP, code=0a6d795f6163636f756e74013300080468656c7001340008047175697401390008012e012a0003117472616e73616374696f6e5f726573657401000004117472616e73616374696f6e5f726573657400010a6e6f5f766f7563686572011a01000a046261636b0130000700031276616c69646174655f726563697069656e74013200041276616c69646174655f726563697069656e74000111696e76616c69645f726563697069656e74011001000110696e766974655f726563697069656e740111010008015f0130000806616d6f756e74012a [D] vm:runner.go:153 state=state @0xc000534300 moves: 31 idx: 0 flags: 0x1253100000000000000000000000000000 path: root/main/send lang: eng (English) [T] vm:runner.go:394 testing sym sym=my_account, input=31 [D] vm:runner.go:152 execute code opcode=8, op=INCMP, code=0468656c7001340008047175697401390008012e012a0003117472616e73616374696f6e5f726573657401000004117472616e73616374696f6e5f726573657400010a6e6f5f766f7563686572011a01000a046261636b0130000700031276616c69646174655f726563697069656e74013200041276616c69646174655f726563697069656e74000111696e76616c69645f726563697069656e74011001000110696e766974655f726563697069656e740111010008015f0130000806616d6f756e74012a [D] vm:runner.go:153 state=state @0xc000534300 moves: 31 idx: 0 flags: 0x1253100000000000000000000000000000 path: root/main/send lang: eng (English) [T] vm:runner.go:394 testing sym sym=help, input=31 [D] vm:runner.go:152 execute code opcode=8, op=INCMP, code=047175697401390008012e012a0003117472616e73616374696f6e5f726573657401000004117472616e73616374696f6e5f726573657400010a6e6f5f766f7563686572011a01000a046261636b0130000700031276616c69646174655f726563697069656e74013200041276616c69646174655f726563697069656e74000111696e76616c69645f726563697069656e74011001000110696e766974655f726563697069656e740111010008015f0130000806616d6f756e74012a [D] vm:runner.go:153 state=state @0xc000534300 moves: 31 idx: 0 flags: 0x1253100000000000000000000000000000 path: root/main/send lang: eng (English) [T] vm:runner.go:394 testing sym sym=quit, input=31 [D] vm:runner.go:152 execute code opcode=8, op=INCMP, code=012e012a0003117472616e73616374696f6e5f726573657401000004117472616e73616374696f6e5f726573657400010a6e6f5f766f7563686572011a01000a046261636b0130000700031276616c69646174655f726563697069656e74013200041276616c69646174655f726563697069656e74000111696e76616c69645f726563697069656e74011001000110696e766974655f726563697069656e740111010008015f0130000806616d6f756e74012a [D] vm:runner.go:153 state=state @0xc000534300 moves: 31 idx: 0 flags: 0x1253100000000000000000000000000000 path: root/main/send lang: eng (English) [T] vm:runner.go:394 testing sym sym=., input=31 [D] vm:runner.go:152 execute code opcode=3, op=LOAD, code=117472616e73616374696f6e5f726573657401000004117472616e73616374696f6e5f726573657400010a6e6f5f766f7563686572011a01000a046261636b0130000700031276616c69646174655f726563697069656e74013200041276616c69646174655f726563697069656e74000111696e76616c69645f726563697069656e74011001000110696e766974655f726563697069656e740111010008015f0130000806616d6f756e74012a [D] vm:runner.go:153 state=state @0xc000534300 moves: 31 idx: 0 flags: 0x1253100000000000000000000000000000 path: root/main/send lang: eng (English) [T] db:db.go:250 made db lookup key lk=202b3235343732343231323232342e000a, pfx=32 [T] postgresdb:pg.go:149 put key=000a, val= [T] db:db.go:250 made db lookup key lk=202b3235343732343231323232342e0009, pfx=32 [T] postgresdb:pg.go:149 put key=0009, val= [D] cache:cache.go:72 Cache add key=transaction_reset, size=0, limit=0 [T] cache:cache.go:73 Cache add data value= [D] vm:runner.go:152 execute code opcode=4, op=RELOAD, code=117472616e73616374696f6e5f726573657400010a6e6f5f766f7563686572011a01000a046261636b0130000700031276616c69646174655f726563697069656e74013200041276616c69646174655f726563697069656e74000111696e76616c69645f726563697069656e74011001000110696e766974655f726563697069656e740111010008015f0130000806616d6f756e74012a [D] vm:runner.go:153 state=state @0xc000534300 moves: 31 idx: 0 flags: 0x1253100000000000000000000000000000 path: root/main/send lang: eng (English) [T] db:db.go:250 made db lookup key lk=202b3235343732343231323232342e000a, pfx=32 [T] postgresdb:pg.go:149 put key=000a, val= [T] db:db.go:250 made db lookup key lk=202b3235343732343231323232342e0009, pfx=32 [T] postgresdb:pg.go:149 put key=0009, val= [T] render:page.go:117 mapped key=transaction_reset [D] vm:runner.go:152 execute code opcode=1, op=CATCH, code=0a6e6f5f766f7563686572011a01000a046261636b0130000700031276616c69646174655f726563697069656e74013200041276616c69646174655f726563697069656e74000111696e76616c69645f726563697069656e74011001000110696e766974655f726563697069656e740111010008015f0130000806616d6f756e74012a [D] vm:runner.go:153 state=state @0xc000534300 moves: 31 idx: 0 flags: 0x1253100000000000000000000000000000 path: root/main/send lang: eng (English) [D] vm:runner.go:152 execute code opcode=10, op=MOUT, code=046261636b0130000700031276616c69646174655f726563697069656e74013200041276616c69646174655f726563697069656e74000111696e76616c69645f726563697069656e74011001000110696e766974655f726563697069656e740111010008015f0130000806616d6f756e74012a [D] vm:runner.go:153 state=state @0xc000534300 moves: 31 idx: 0 flags: 0x1253100000000000000000000000000000 path: root/main/send lang: eng (English) [D] vm:runner.go:152 execute code opcode=7, op=HALT, code=00031276616c69646174655f726563697069656e74013200041276616c69646174655f726563697069656e74000111696e76616c69645f726563697069656e74011001000110696e766974655f726563697069656e740111010008015f0130000806616d6f756e74012a [D] vm:runner.go:153 state=state @0xc000534300 moves: 31 idx: 0 flags: 0x1253100000000000000000000000000000 path: root/main/send lang: eng (English) [D] vm:runner.go:438 found HALT, stopping [D] engine:db.go:540 end VM run code=00031276616c69646174655f726563697069656e74013200041276616c69646174655f726563697069656e74000111696e76616c69645f726563697069656e74011001000110696e766974655f726563697069656e740111010008015f0130000806616d6f756e74012a, state=state @0xc000534300 moves: 31 idx: 0 flags: 0x1653100000000000000000000000000000 path: root/main/send lang: eng (English), vm=vm (0xc0000584e0) ok [D] state:state.go:346 code changed (set) code=00031276616c69646174655f726563697069656e74013200041276616c69646174655f726563697069656e74000111696e76616c69645f726563697069656e74011001000110696e766974655f726563697069656e740111010008015f0130000806616d6f756e74012a [T] engine:db.go:572 render with state state=state @0xc000534300 moves: 31 idx: 0 flags: 0x1653100000000000000000000000000000 path: root/main/send lang: eng (English) [I] render:page.go:234 found sink sym=send, sink=transaction_reset [D] render:size.go:87 Added cursor offset=0 [T] db:db.go:245 language using ln=eng (English) [T] db:db.go:250 made db lookup key lk=0473656e64, pfx=4 [T] fsdb:fs.go:111 trying fs get i=0, key=73656e64, path=/var/www/html/golang/sarafu-vise/services/registration/4send_eng [T] fsdb:fs.go:111 trying fs get i=1, key=73656e64, path=/var/www/html/golang/sarafu-vise/services/registration/send_eng [T] fsdb:fs.go:111 trying fs get i=2, key=73656e64, path=/var/www/html/golang/sarafu-vise/services/registration/4send [T] fsdb:fs.go:111 trying fs get i=3, key=73656e64, path=/var/www/html/golang/sarafu-vise/services/registration/send [T] render:size.go:100 check values k=transaction_reset, v=, idx=0, cursors=[0] [D] render:page.go:175 render for index=0 [D] render:page.go:391 rendered template bytes=45 [T] db:db.go:245 language using ln=eng (English) [T] db:db.go:250 made db lookup key lk=026261636b5f6d656e75, pfx=2 [T] fsdb:fs.go:111 trying fs get i=0, key=6261636b5f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/2back_menu_eng [T] fsdb:fs.go:111 trying fs get i=1, key=6261636b5f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/back_menu_eng [T] fsdb:fs.go:111 trying fs get i=2, key=6261636b5f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/2back_menu [T] fsdb:fs.go:111 trying fs get i=3, key=6261636b5f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/back_menu [D] render:page.go:400 rendered menu bytes=7 [D] render:menu.go:261 applypage m=pagecount: 2 menusink: false next: false prev: false, idx=0 [D] render:menu.go:261 applypage m=pagecount: 2 menusink: false next: false prev: false, idx=1 [D] render:page.go:361 calculated pre-navigation allocation bytes=107, menusizes=[0 0 0 0] [T] render:page.go:267 processing sink idx=0, value=, netremaining=106, l=0 [T] render:page.go:377 nosinkvalue idx=0, value= [T] db:db.go:245 language using ln=eng (English) [T] db:db.go:250 made db lookup key lk=0473656e64, pfx=4 [T] fsdb:fs.go:111 trying fs get i=0, key=73656e64, path=/var/www/html/golang/sarafu-vise/services/registration/4send_eng [T] fsdb:fs.go:111 trying fs get i=1, key=73656e64, path=/var/www/html/golang/sarafu-vise/services/registration/send_eng [T] fsdb:fs.go:111 trying fs get i=2, key=73656e64, path=/var/www/html/golang/sarafu-vise/services/registration/4send [T] fsdb:fs.go:111 trying fs get i=3, key=73656e64, path=/var/www/html/golang/sarafu-vise/services/registration/send [T] render:size.go:100 check values k=transaction_reset, v=, idx=0, cursors=[0] [D] render:page.go:175 render for index=0 [D] render:page.go:391 rendered template bytes=45 [T] db:db.go:245 language using ln=eng (English) [T] db:db.go:250 made db lookup key lk=026261636b5f6d656e75, pfx=2 [T] fsdb:fs.go:111 trying fs get i=0, key=6261636b5f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/2back_menu_eng [T] fsdb:fs.go:111 trying fs get i=1, key=6261636b5f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/back_menu_eng [T] fsdb:fs.go:111 trying fs get i=2, key=6261636b5f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/2back_menu [T] fsdb:fs.go:111 trying fs get i=3, key=6261636b5f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/back_menu [D] render:page.go:400 rendered menu bytes=7 [I] persist:persist.go:100 saving state and cache self=persister @0xc00051e4c0 state:0xc000534300 cache:0xc000490240, key=+254724212224, state=state @0xc000534300 moves: 31 idx: 0 flags: 0x0653100000000000000000000000000000 path: root/main/send lang: eng (English) [T] persist:persist.go:101 saving bytecode code=00031276616c69646174655f726563697069656e74013200041276616c69646174655f726563697069656e74000111696e76616c69645f726563697069656e74011001000110696e766974655f726563697069656e740111010008015f0130000806616d6f756e74012a [T] db:db.go:250 made db lookup key lk=102b323534373234323132323234, pfx=16 [T] postgresdb:pg.go:93 begin single tx err= [T] postgresdb:pg.go:149 put key=2b323534373234323132323234, val=a2655374617465a764436f6465586a00031276616c69646174655f726563697069656e74013200041276616c69646174655f726563697069656e74000111696e76616c69645f726563697069656e74011001000110696e766974655f726563697069656e740111010008015f0130000806616d6f756e74012a6845786563506174688364726f6f74646d61696e6473656e646742697453697a6518886753697a654964780065466c616773510653100000000000000000000000000000654d6f766573181f684c616e6775616765a264436f646563656e67644e616d6567456e676c697368664d656d6f7279a569436163686553697a65006c436163686555736553697a651365436163686584a0a374636865636b5f626c6f636b65645f7374617475736075636865636b5f6163636f756e745f637265617465646074636865636b5f6163636f756e745f73746174757360a375636c6561725f74656d706f726172795f76616c7565606f6d616e6167655f766f756368657273606d636865636b5f62616c616e63657342616c616e63653a2031302e3030205045530aa1717472616e73616374696f6e5f7265736574606553697a6573a76f6d616e6167655f766f75636865727318a06d636865636b5f62616c616e63651880717472616e73616374696f6e5f72657365740074636865636b5f626c6f636b65645f7374617475730175636865636b5f6163636f756e745f637265617465640274636865636b5f6163636f756e745f7374617475730075636c6561725f74656d706f726172795f76616c756502694c61737456616c756560 [T] postgresdb:pg.go:113 stop single tx err= [T] persist:persist.go:107 state and cache flushed from persister [T] engine:db.go:389 that's a wrap engine=&{0xc000534300 0xc000490240 0xc0000584e0 0xc00009de00 0xc00051e4c0 {160 +254724212224 root 128 0 false false : true} 0x9f6000 true false true 0} [T] postgresdb:pg.go:123 stop multi tx err= [D] atserver:parse.go:48 Received request: {"body":"channel=\u0026phoneNumber=%2B254724212224\u0026serviceCode=%2A483%2A061%23\u0026sessionId=DialogussSession__8294257475936592432\u0026text=0712345678"}=?? [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, 127.0.0.1:7123).WithCancel.WithCancel sessionid '+254724212224', rootpath 'root', flagcount 128, language '' [48 55 49 50 51 52 53 54 55 56] 0xc0000f20e0 false} [T] postgresdb:pg.go:93 begin single tx err= [D] engine:db.go:214 ca ca=&{0 0 [map[]] map[check_account_created:2 check_account_status:0 check_balance:128 check_blocked_status:1 clear_temporary_value:2 manage_vouchers:160 transaction_reset:0] false} [T] db:db.go:250 made db lookup key lk=102b323534373234323132323234, pfx=16 [T] postgresdb:pg.go:93 begin single tx err= [T] postgresdb:pg.go:176 get key=2b323534373234323132323234 [T] postgresdb:pg.go:113 stop single tx err= [I] persist:persist.go:126 loaded state and cache self=persister @0xc00051e4c0 state:0xc000534600 cache:0xc000490240, key=+254724212224, state=state @0xc000534600 moves: 31 idx: 0 flags: 0x0653100000000000000000000000000000 path: root/main/send lang: eng (English) [T] persist:persist.go:127 loaded bytecode code=00031276616c69646174655f726563697069656e74013200041276616c69646174655f726563697069656e74000111696e76616c69645f726563697069656e74011001000110696e766974655f726563697069656e740111010008015f0130000806616d6f756e74012a [T] engine:db.go:264 set persister st=state @0xc000534600 moves: 31 idx: 0 flags: 0x0653100000000000000000000000000000 path: root/main/send lang: eng (English), cac=&{0 19 [map[] map[check_account_created: check_account_status: check_blocked_status:] map[check_balance:Balance: 10.00 PES clear_temporary_value: manage_vouchers:] map[transaction_reset:]] map[check_account_created:2 check_account_status:0 check_balance:128 check_blocked_status:1 clear_temporary_value:2 manage_vouchers:160 transaction_reset:0] false}, session=+254724212224, persister=persister @0xc00051e4c0 state:0xc000534600 cache:0xc000490240 [I] vm:runner.go:63 vm created with state state=state @0xc000534600 moves: 31 idx: 0 flags: 0x0653100000000000000000000000000000 path: root/main/send 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 @0xc000534600 moves: 32 idx: 0 flags: 0x0653100000000000000000000000000000 path: root/main/send/_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 @0xc000534600 moves: 32 idx: 0 flags: 0x1053100000000000000000000000000000 path: root/main/send/_first lang: eng (English) [D] ussdmenuhandler:menuhandler.go:146 handler has been initialized state=state @0xc000534600 moves: 32 idx: 0 flags: 0x1053100000000000000000000000000000 path: root/main/send/_first lang: eng (English), cache=&{0 19 [map[] map[check_account_created: check_account_status: check_blocked_status:] map[check_balance:Balance: 10.00 PES clear_temporary_value: manage_vouchers:] map[transaction_reset:] map[]] map[check_account_created:2 check_account_status:0 check_balance:128 check_blocked_status:1 clear_temporary_value:2 manage_vouchers:160 transaction_reset:0] false}, x-SessionId=+254724212224 [D] cache:cache.go:72 Cache add key=_first, size=0, limit=0 [T] cache:cache.go:73 Cache add data value= [D] vm:runner.go:152 execute code opcode=7, op=HALT, code= [D] vm:runner.go:153 state=state @0xc000534600 moves: 32 idx: 0 flags: 0x1053100000000000000000000000000000 path: root/main/send/_first lang: eng (English) [D] vm:runner.go:438 found HALT, stopping [D] engine:db.go:361 end pre-VM check [T] state:state.go:319 execpath before path=[root main send _first] [T] state:state.go:326 execpath after path=[root main send] [D] cache:cache.go:165 Cache free frame=4, key=_first, size=0 [I] engine:db.go:524 new VM execution with input input=30373132333435363738 [D] engine:db.go:533 start VM run code=00031276616c69646174655f726563697069656e74013200041276616c69646174655f726563697069656e74000111696e76616c69645f726563697069656e74011001000110696e766974655f726563697069656e740111010008015f0130000806616d6f756e74012a [T] vm:runner.go:120 new vm run [D] vm:runner.go:152 execute code opcode=3, op=LOAD, code=1276616c69646174655f726563697069656e74013200041276616c69646174655f726563697069656e74000111696e76616c69645f726563697069656e74011001000110696e766974655f726563697069656e740111010008015f0130000806616d6f756e74012a [D] vm:runner.go:153 state=state @0xc000534600 moves: 33 idx: 0 flags: 0x1053100000000000000000000000000000 path: root/main/send lang: eng (English) ====== running ValidateRecipient ========= [T] db:db.go:250 made db lookup key lk=202b3235343732343231323232342e000b, pfx=32 [T] postgresdb:pg.go:149 put key=000b, val=30373132333435363738 [T] db:db.go:250 made db lookup key lk=202b3235343731323334353637382e0001, pfx=32 [T] postgresdb:pg.go:176 get key=0001 [I] postgresdb:pg.go:129 aborting tx tx=&{0xc000480048 0xc00047b928} [I] ussdmenuhandler:menuhandler.go:1559 Unregistered phone number: %s 0712345678=x-SessionId, +254724212224=?? [D] cache:cache.go:72 Cache add key=validate_recipient, size=10, limit=50 [T] cache:cache.go:73 Cache add data value=0712345678 [D] vm:runner.go:152 execute code opcode=4, op=RELOAD, code=1276616c69646174655f726563697069656e74000111696e76616c69645f726563697069656e74011001000110696e766974655f726563697069656e740111010008015f0130000806616d6f756e74012a [D] vm:runner.go:153 state=state @0xc000534600 moves: 33 idx: 0 flags: 0x1053120000000000000000000000000000 path: root/main/send lang: eng (English) ====== running ValidateRecipient ========= [T] db:db.go:250 made db lookup key lk=202b3235343732343231323232342e000b, pfx=32 [T] postgresdb:pg.go:93 begin single tx err= [T] postgresdb:pg.go:149 put key=000b, val=30373132333435363738 [T] db:db.go:250 made db lookup key lk=202b3235343731323334353637382e0001, pfx=32 [T] postgresdb:pg.go:176 get key=0001 [I] postgresdb:pg.go:129 aborting tx tx=&{0xc0004805b8 0xc00047b918} [I] ussdmenuhandler:menuhandler.go:1559 Unregistered phone number: %s 0712345678=x-SessionId, +254724212224=?? [T] render:page.go:117 mapped key=validate_recipient [D] vm:runner.go:152 execute code opcode=1, op=CATCH, code=11696e76616c69645f726563697069656e74011001000110696e766974655f726563697069656e740111010008015f0130000806616d6f756e74012a [D] vm:runner.go:153 state=state @0xc000534600 moves: 33 idx: 0 flags: 0x1053120000000000000000000000000000 path: root/main/send lang: eng (English) [D] vm:runner.go:152 execute code opcode=1, op=CATCH, code=10696e766974655f726563697069656e740111010008015f0130000806616d6f756e74012a [D] vm:runner.go:153 state=state @0xc000534600 moves: 33 idx: 0 flags: 0x1053120000000000000000000000000000 path: root/main/send lang: eng (English) [I] vm:runner.go:276 catch! flag=17, sym=invite_recipient, target=invite_recipient, mode=true [T] resource:db.go:117 getcode sym=invite_recipient [T] db:db.go:250 made db lookup key lk=01696e766974655f726563697069656e74, pfx=1 [T] fsdb:fs.go:108 fs get skip missing i=0 [T] fsdb:fs.go:108 fs get skip missing i=1 [T] fsdb:fs.go:111 trying fs get i=2, key=696e766974655f726563697069656e74, path=/var/www/html/golang/sarafu-vise/services/registration/1invite_recipient [T] fsdb:fs.go:111 trying fs get i=3, key=696e766974655f726563697069656e74, path=/var/www/html/golang/sarafu-vise/services/registration/invite_recipient.bin [D] vm:runner.go:152 execute code opcode=5, op=MAP, code=1276616c69646174655f726563697069656e74000a0572657472790131000a06696e766974650132000a0471756974013900070008015f013100080d696e766974655f726573756c740132000804717569740139 [D] vm:runner.go:153 state=state @0xc000534600 moves: 34 idx: 0 flags: 0x1053120000000000000000000000000000 path: root/main/send/invite_recipient lang: eng (English) [T] render:page.go:117 mapped key=validate_recipient [D] vm:runner.go:152 execute code opcode=10, op=MOUT, code=0572657472790131000a06696e766974650132000a0471756974013900070008015f013100080d696e766974655f726573756c740132000804717569740139 [D] vm:runner.go:153 state=state @0xc000534600 moves: 34 idx: 0 flags: 0x1053120000000000000000000000000000 path: root/main/send/invite_recipient lang: eng (English) [D] vm:runner.go:152 execute code opcode=10, op=MOUT, code=06696e766974650132000a0471756974013900070008015f013100080d696e766974655f726573756c740132000804717569740139 [D] vm:runner.go:153 state=state @0xc000534600 moves: 34 idx: 0 flags: 0x1053120000000000000000000000000000 path: root/main/send/invite_recipient lang: eng (English) [D] vm:runner.go:152 execute code opcode=10, op=MOUT, code=0471756974013900070008015f013100080d696e766974655f726573756c740132000804717569740139 [D] vm:runner.go:153 state=state @0xc000534600 moves: 34 idx: 0 flags: 0x1053120000000000000000000000000000 path: root/main/send/invite_recipient lang: eng (English) [D] vm:runner.go:152 execute code opcode=7, op=HALT, code=0008015f013100080d696e766974655f726573756c740132000804717569740139 [D] vm:runner.go:153 state=state @0xc000534600 moves: 34 idx: 0 flags: 0x1053120000000000000000000000000000 path: root/main/send/invite_recipient lang: eng (English) [D] vm:runner.go:438 found HALT, stopping [D] engine:db.go:540 end VM run code=0008015f013100080d696e766974655f726573756c740132000804717569740139, state=state @0xc000534600 moves: 34 idx: 0 flags: 0x1453120000000000000000000000000000 path: root/main/send/invite_recipient lang: eng (English), vm=vm (0xc0005d6240) ok [D] state:state.go:346 code changed (set) code=0008015f013100080d696e766974655f726573756c740132000804717569740139 [T] engine:db.go:572 render with state state=state @0xc000534600 moves: 34 idx: 0 flags: 0x1453120000000000000000000000000000 path: root/main/send/invite_recipient lang: eng (English) [T] render:page.go:240 no sink found sym=invite_recipient [D] render:size.go:87 Added cursor offset=0 [T] db:db.go:245 language using ln=eng (English) [T] db:db.go:250 made db lookup key lk=04696e766974655f726563697069656e74, pfx=4 [T] fsdb:fs.go:111 trying fs get i=0, key=696e766974655f726563697069656e74, path=/var/www/html/golang/sarafu-vise/services/registration/4invite_recipient_eng [T] fsdb:fs.go:111 trying fs get i=1, key=696e766974655f726563697069656e74, path=/var/www/html/golang/sarafu-vise/services/registration/invite_recipient_eng [T] fsdb:fs.go:111 trying fs get i=2, key=696e766974655f726563697069656e74, path=/var/www/html/golang/sarafu-vise/services/registration/4invite_recipient [T] fsdb:fs.go:111 trying fs get i=3, key=696e766974655f726563697069656e74, path=/var/www/html/golang/sarafu-vise/services/registration/invite_recipient [D] render:page.go:175 render for index=0 [D] render:page.go:391 rendered template bytes=47 [T] db:db.go:245 language using ln=eng (English) [T] db:db.go:250 made db lookup key lk=0272657472795f6d656e75, pfx=2 [T] fsdb:fs.go:111 trying fs get i=0, key=72657472795f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/2retry_menu_eng [T] fsdb:fs.go:111 trying fs get i=1, key=72657472795f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/retry_menu_eng [T] fsdb:fs.go:111 trying fs get i=2, key=72657472795f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/2retry_menu [T] fsdb:fs.go:111 trying fs get i=3, key=72657472795f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/retry_menu [T] db:db.go:245 language using ln=eng (English) [T] db:db.go:250 made db lookup key lk=02696e766974655f6d656e75, pfx=2 [T] fsdb:fs.go:111 trying fs get i=0, key=696e766974655f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/2invite_menu_eng [T] fsdb:fs.go:111 trying fs get i=1, key=696e766974655f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/invite_menu_eng [T] fsdb:fs.go:111 trying fs get i=2, key=696e766974655f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/2invite_menu [T] fsdb:fs.go:111 trying fs get i=3, key=696e766974655f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/invite_menu [T] db:db.go:245 language using ln=eng (English) [T] db:db.go:250 made db lookup key lk=02717569745f6d656e75, pfx=2 [T] fsdb:fs.go:111 trying fs get i=0, key=717569745f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/2quit_menu_eng [T] fsdb:fs.go:111 trying fs get i=1, key=717569745f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/quit_menu_eng [T] fsdb:fs.go:111 trying fs get i=2, key=717569745f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/2quit_menu [T] fsdb:fs.go:111 trying fs get i=3, key=717569745f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/quit_menu [D] render:page.go:400 rendered menu bytes=41 [D] render:menu.go:261 applypage m=pagecount: 2 menusink: false next: false prev: false, idx=0 [D] render:menu.go:261 applypage m=pagecount: 2 menusink: false next: false prev: false, idx=1 [D] render:page.go:361 calculated pre-navigation allocation bytes=71, menusizes=[0 0 0 0] [T] render:page.go:377 nosinkvalue idx=0, value= [T] db:db.go:245 language using ln=eng (English) [T] db:db.go:250 made db lookup key lk=04696e766974655f726563697069656e74, pfx=4 [T] fsdb:fs.go:111 trying fs get i=0, key=696e766974655f726563697069656e74, path=/var/www/html/golang/sarafu-vise/services/registration/4invite_recipient_eng [T] fsdb:fs.go:111 trying fs get i=1, key=696e766974655f726563697069656e74, path=/var/www/html/golang/sarafu-vise/services/registration/invite_recipient_eng [T] fsdb:fs.go:111 trying fs get i=2, key=696e766974655f726563697069656e74, path=/var/www/html/golang/sarafu-vise/services/registration/4invite_recipient [T] fsdb:fs.go:111 trying fs get i=3, key=696e766974655f726563697069656e74, path=/var/www/html/golang/sarafu-vise/services/registration/invite_recipient [D] render:page.go:175 render for index=0 [D] render:page.go:391 rendered template bytes=47 [T] db:db.go:245 language using ln=eng (English) [T] db:db.go:250 made db lookup key lk=0272657472795f6d656e75, pfx=2 [T] fsdb:fs.go:111 trying fs get i=0, key=72657472795f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/2retry_menu_eng [T] fsdb:fs.go:111 trying fs get i=1, key=72657472795f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/retry_menu_eng [T] fsdb:fs.go:111 trying fs get i=2, key=72657472795f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/2retry_menu [T] fsdb:fs.go:111 trying fs get i=3, key=72657472795f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/retry_menu [T] db:db.go:245 language using ln=eng (English) [T] db:db.go:250 made db lookup key lk=02696e766974655f6d656e75, pfx=2 [T] fsdb:fs.go:111 trying fs get i=0, key=696e766974655f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/2invite_menu_eng [T] fsdb:fs.go:111 trying fs get i=1, key=696e766974655f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/invite_menu_eng [T] fsdb:fs.go:111 trying fs get i=2, key=696e766974655f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/2invite_menu [T] fsdb:fs.go:111 trying fs get i=3, key=696e766974655f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/invite_menu [T] db:db.go:245 language using ln=eng (English) [T] db:db.go:250 made db lookup key lk=02717569745f6d656e75, pfx=2 [T] fsdb:fs.go:111 trying fs get i=0, key=717569745f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/2quit_menu_eng [T] fsdb:fs.go:111 trying fs get i=1, key=717569745f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/quit_menu_eng [T] fsdb:fs.go:111 trying fs get i=2, key=717569745f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/2quit_menu [T] fsdb:fs.go:111 trying fs get i=3, key=717569745f6d656e75, path=/var/www/html/golang/sarafu-vise/services/registration/quit_menu [D] render:page.go:400 rendered menu bytes=41 [I] persist:persist.go:100 saving state and cache self=persister @0xc00051e4c0 state:0xc000534600 cache:0xc000490240, key=+254724212224, state=state @0xc000534600 moves: 34 idx: 0 flags: 0x0453120000000000000000000000000000 path: root/main/send/invite_recipient lang: eng (English) [T] persist:persist.go:101 saving bytecode code=0008015f013100080d696e766974655f726573756c740132000804717569740139 [T] db:db.go:250 made db lookup key lk=102b323534373234323132323234, pfx=16 [T] postgresdb:pg.go:93 begin single tx err= [T] postgresdb:pg.go:149 put key=2b323534373234323132323234, val=a2655374617465a764436f646558210008015f013100080d696e766974655f726573756c7401320008047175697401396845786563506174688464726f6f74646d61696e6473656e6470696e766974655f726563697069656e746742697453697a6518886753697a654964780065466c616773510453120000000000000000000000000000654d6f7665731822684c616e6775616765a264436f646563656e67644e616d6567456e676c697368664d656d6f7279a569436163686553697a65006c436163686555736553697a65181d65436163686585a0a374636865636b5f626c6f636b65645f7374617475736075636865636b5f6163636f756e745f637265617465646074636865636b5f6163636f756e745f73746174757360a375636c6561725f74656d706f726172795f76616c7565606f6d616e6167655f766f756368657273606d636865636b5f62616c616e63657342616c616e63653a2031302e3030205045530aa2717472616e73616374696f6e5f7265736574607276616c69646174655f726563697069656e746a30373132333435363738a06553697a6573a875636865636b5f6163636f756e745f637265617465640274636865636b5f6163636f756e745f7374617475730075636c6561725f74656d706f726172795f76616c7565026f6d616e6167655f766f75636865727318a06d636865636b5f62616c616e63651880717472616e73616374696f6e5f7265736574007276616c69646174655f726563697069656e74183274636865636b5f626c6f636b65645f73746174757301694c61737456616c75656a30373132333435363738 [T] postgresdb:pg.go:113 stop single tx err= [T] persist:persist.go:107 state and cache flushed from persister [T] engine:db.go:389 that's a wrap engine=&{0xc000534600 0xc000490240 0xc0005d6240 0xc00009de00 0xc00051e4c0 {160 +254724212224 root 128 0 false false : true} 0x9f6000 true false true 0} [D] atserver:parse.go:48 Received request: {"body":"channel=\u0026phoneNumber=%2B254724212224\u0026serviceCode=%2A483%2A061%23\u0026sessionId=DialogussSession__8294257475936592432\u0026text=2"}=?? [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, 127.0.0.1:7123).WithCancel.WithCancel sessionid '+254724212224', rootpath 'root', flagcount 128, language '' [50] 0xc00054a380 false} [T] postgresdb:pg.go:93 begin single tx err= [D] engine:db.go:214 ca ca=&{0 0 [map[]] map[check_account_created:2 check_account_status:0 check_balance:128 check_blocked_status:1 clear_temporary_value:2 manage_vouchers:160 transaction_reset:0 validate_recipient:50] 0712345678 false} [T] db:db.go:250 made db lookup key lk=102b323534373234323132323234, pfx=16 [T] postgresdb:pg.go:93 begin single tx err= [T] postgresdb:pg.go:176 get key=2b323534373234323132323234 [T] postgresdb:pg.go:113 stop single tx err= [I] persist:persist.go:126 loaded state and cache self=persister @0xc00051e4c0 state:0xc0000ed900 cache:0xc000490240, key=+254724212224, state=state @0xc0000ed900 moves: 34 idx: 0 flags: 0x0453120000000000000000000000000000 path: root/main/send/invite_recipient lang: eng (English) [T] persist:persist.go:127 loaded bytecode code=0008015f013100080d696e766974655f726573756c740132000804717569740139 [T] engine:db.go:264 set persister st=state @0xc0000ed900 moves: 34 idx: 0 flags: 0x0453120000000000000000000000000000 path: root/main/send/invite_recipient lang: eng (English), cac=&{0 29 [map[] map[check_account_created: check_account_status: check_blocked_status:] map[check_balance:Balance: 10.00 PES clear_temporary_value: manage_vouchers:] map[transaction_reset: validate_recipient:0712345678] map[]] map[check_account_created:2 check_account_status:0 check_balance:128 check_blocked_status:1 clear_temporary_value:2 manage_vouchers:160 transaction_reset:0 validate_recipient:50] 0712345678 false}, session=+254724212224, persister=persister @0xc00051e4c0 state:0xc0000ed900 cache:0xc000490240 [I] vm:runner.go:63 vm created with state state=state @0xc0000ed900 moves: 34 idx: 0 flags: 0x0453120000000000000000000000000000 path: root/main/send/invite_recipient 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 @0xc0000ed900 moves: 35 idx: 0 flags: 0x0453120000000000000000000000000000 path: root/main/send/invite_recipient/_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 @0xc0000ed900 moves: 35 idx: 0 flags: 0x1053120000000000000000000000000000 path: root/main/send/invite_recipient/_first lang: eng (English) [D] ussdmenuhandler:menuhandler.go:146 handler has been initialized state=state @0xc0000ed900 moves: 35 idx: 0 flags: 0x1053120000000000000000000000000000 path: root/main/send/invite_recipient/_first lang: eng (English), cache=&{0 29 [map[] map[check_account_created: check_account_status: check_blocked_status:] map[check_balance:Balance: 10.00 PES clear_temporary_value: manage_vouchers:] map[transaction_reset: validate_recipient:0712345678] map[] map[]] map[check_account_created:2 check_account_status:0 check_balance:128 check_blocked_status:1 clear_temporary_value:2 manage_vouchers:160 transaction_reset:0 validate_recipient:50] 0712345678 false}, x-SessionId=+254724212224 [D] cache:cache.go:72 Cache add key=_first, size=0, limit=0 [T] cache:cache.go:73 Cache add data value= [D] vm:runner.go:152 execute code opcode=7, op=HALT, code= [D] vm:runner.go:153 state=state @0xc0000ed900 moves: 35 idx: 0 flags: 0x1053120000000000000000000000000000 path: root/main/send/invite_recipient/_first lang: eng (English) [D] vm:runner.go:438 found HALT, stopping [D] engine:db.go:361 end pre-VM check [T] state:state.go:319 execpath before path=[root main send invite_recipient _first] [T] state:state.go:326 execpath after path=[root main send invite_recipient] [D] cache:cache.go:165 Cache free frame=5, key=_first, size=0 [I] engine:db.go:524 new VM execution with input input=32 [D] engine:db.go:533 start VM run code=0008015f013100080d696e766974655f726573756c740132000804717569740139 [T] vm:runner.go:120 new vm run [D] vm:runner.go:152 execute code opcode=8, op=INCMP, code=015f013100080d696e766974655f726573756c740132000804717569740139 [D] vm:runner.go:153 state=state @0xc0000ed900 moves: 36 idx: 0 flags: 0x1053120000000000000000000000000000 path: root/main/send/invite_recipient lang: eng (English) [T] vm:runner.go:394 testing sym sym=_, input=32 [D] vm:runner.go:152 execute code opcode=8, op=INCMP, code=0d696e766974655f726573756c740132000804717569740139 [D] vm:runner.go:153 state=state @0xc0000ed900 moves: 36 idx: 0 flags: 0x1153120000000000000000000000000000 path: root/main/send/invite_recipient lang: eng (English) [T] vm:runner.go:394 testing sym sym=invite_result, input=32 [I] vm:runner.go:402 input match input=32, next=invite_result [T] resource:db.go:117 getcode sym=invite_result [T] db:db.go:250 made db lookup key lk=01696e766974655f726573756c74, pfx=1 [T] fsdb:fs.go:108 fs get skip missing i=0 [T] fsdb:fs.go:108 fs get skip missing i=1 [T] fsdb:fs.go:111 trying fs get i=2, key=696e766974655f726573756c74, path=/var/www/html/golang/sarafu-vise/services/registration/1invite_result [T] fsdb:fs.go:111 trying fs get i=3, key=696e766974655f726573756c74, path=/var/www/html/golang/sarafu-vise/services/registration/invite_result.bin [D] vm:runner.go:426 loaded additional code next=invite_result, code=000316696e766974655f76616c69645f726563697069656e7401000007 [D] vm:runner.go:152 execute code opcode=8, op=INCMP, code=04717569740139000316696e766974655f76616c69645f726563697069656e7401000007 [D] vm:runner.go:153 state=state @0xc0000ed900 moves: 37 idx: 0 flags: 0x1253120000000000000000000000000000 path: root/main/send/invite_recipient/invite_result lang: eng (English) [T] vm:runner.go:394 testing sym sym=quit, input=32 [D] vm:runner.go:152 execute code opcode=3, op=LOAD, code=16696e766974655f76616c69645f726563697069656e7401000007 [D] vm:runner.go:153 state=state @0xc0000ed900 moves: 37 idx: 0 flags: 0x1253120000000000000000000000000000 path: root/main/send/invite_recipient/invite_result lang: eng (English) ====== running InviteValidRecipient ====== [T] db:db.go:250 made db lookup key lk=202b3235343732343231323232342e000b, pfx=32 [T] postgresdb:pg.go:176 get key=000b the recipient from temporary_value: $2a$08$FP.3f4A7ESmZBeEo2OAHG.oK0z3cAcMhWoHjkRynuZHdvdqWbGw42 [I] ussdmenuhandler:menuhandler.go:1676 corrupted recipient key=11, recipient=2432612430382446502e336634413745536d5a4265456f324f4148472e6f4b307a336341634d68576f486a6b52796e755a4864766471576247773432, x-SessionId=+254724212224 [D] cache:cache.go:72 Cache add key=invite_valid_recipient, size=0, limit=0 [T] cache:cache.go:73 Cache add data value= [D] vm:runner.go:152 execute code opcode=7, op=HALT, code= [D] vm:runner.go:153 state=state @0xc0000ed900 moves: 37 idx: 0 flags: 0x1253120000000000000000000000000000 path: root/main/send/invite_recipient/invite_result lang: eng (English) [D] vm:runner.go:438 found HALT, stopping [D] engine:db.go:540 end VM run code=, state=state @0xc0000ed900 moves: 37 idx: 0 flags: 0x1653120000000000000000000000000000 path: root/main/send/invite_recipient/invite_result lang: eng (English), vm=vm (0xc000059bc0) ok [D] state:state.go:346 code changed (set) code= [I] engine:db.go:400 runner finished with no remaining code state=state @0xc0000ed900 moves: 37 idx: 0 flags: 0x1653120000000000000000000000000000 path: root/main/send/invite_recipient/invite_result lang: eng (English) [D] engine:db.go:402 have output for quitting [T] engine:db.go:572 render with state state=state @0xc0000ed900 moves: 37 idx: 0 flags: 0x1653120000000000000000000000000000 path: root/main/send/invite_recipient/invite_result lang: eng (English) [T] render:page.go:240 no sink found sym=invite_result [D] render:size.go:87 Added cursor offset=0 [T] db:db.go:245 language using ln=eng (English) [T] db:db.go:250 made db lookup key lk=04696e766974655f726573756c74, pfx=4 [T] fsdb:fs.go:111 trying fs get i=0, key=696e766974655f726573756c74, path=/var/www/html/golang/sarafu-vise/services/registration/4invite_result_eng [T] fsdb:fs.go:111 trying fs get i=1, key=696e766974655f726573756c74, path=/var/www/html/golang/sarafu-vise/services/registration/invite_result_eng [T] fsdb:fs.go:111 trying fs get i=2, key=696e766974655f726573756c74, path=/var/www/html/golang/sarafu-vise/services/registration/4invite_result [T] fsdb:fs.go:111 trying fs get i=3, key=696e766974655f726573756c74, path=/var/www/html/golang/sarafu-vise/services/registration/invite_result 2025/04/25 13:34:14 http: superfluous response.WriteHeader call from git.grassecon.net/grassrootseconomics/visedriver-africastalking/africastalking.(*ATRequestHandler).WriteError (server.go:105)