See https://jenkins.osmocom.org/jenkins/job/ttcn3-remsim-test-asan/691/display/redirect?page=changes
Changes:
[Andreas Eversberg] Fix bankd connection at RemsimClient_Tests.TC_bank_disconnect_reconnect
[Andreas Eversberg] Fix access pcscd in various RemsimBankd_Tests
[Andreas Eversberg] testenv: Allow adding extra parameters to podman
------------------------------------------ [...truncated 103.62 KiB...] RSPRO_SRV0(3)@4a2bd02e722f: IPA: Closed MTC@4a2bd02e722f: setverdict(pass): pass -> pass, component reason not changed [38;5;23m4814 [1;31mDLINP[0;m[38;5;23m [1;31mERROR[0;m[38;5;23m stream_cli.c:565 CLICONN(server,r=127.0.0.10:9998<->l=127.0.0.1:35089){CONNECTED} lost connection with srv (-104)[0;m [38;5;23m4814 [1;34mDLINP[0;m[38;5;23m [1;34mDEBUG[0;m[38;5;23m stream_cli.c:181 CLICONN(server,r=127.0.0.10:9998<->l=127.0.0.1:35089){CONNECTED} close()[0;m 4814 [1;33mDRSPRO[0;m [1;33mNOTICE[0;m ../rspro_client_fsm.c:154 RSPRO_CLIENT(server){ESTABLISHED}: RSPRO link to 127.0.0.10:9998 DOWN [38;5;23m4814 [1;32mDLINP[0;m[38;5;23m [1;32mINFO[0;m[38;5;23m ipa_keepalive.c:351 IPA-KA(server){WAIT_RESP}: Stopping IPA keep-alive FSM[0;m [38;5;23m4814 [1;34mDLINP[0;m[38;5;23m [1;34mDEBUG[0;m[38;5;23m ipa_keepalive.c:352 IPA-KA(server){WAIT_RESP}: Received Event OSMO_IPA_KA_E_STOP[0;m [38;5;23m4814 [1;34mDLINP[0;m[38;5;23m [1;34mDEBUG[0;m[38;5;23m ipa_keepalive.c:159 IPA-KA(server){WAIT_RESP}: state_chg to INIT[0;m [38;5;23m4814 [1;34mDLINP[0;m[38;5;23m [1;34mDEBUG[0;m[38;5;23m fsm.c:569 IPA-KA(server){INIT}: Deallocated[0;m 4814 [1;34mDRSPRO[0;m [1;34mDEBUG[0;m ../rspro_client_fsm.c:162 RSPRO_CLIENT(server){ESTABLISHED}: Received Event SRVC_E_TCP_DOWN 4814 [1;34mDRSPRO[0;m [1;34mDEBUG[0;m ../rspro_client_fsm.c:310 RSPRO_CLIENT(server){ESTABLISHED}: ->REESTABLISH_DELAY delay 995ms; 5ms since last attempt [step 3/123@1s] 4814 [1;34mDRSPRO[0;m [1;34mDEBUG[0;m ../rspro_client_fsm.c:318 RSPRO_CLIENT(server){ESTABLISHED}: state_chg to REESTABLISH_DELAY 4814 [1;32mDRSPRO[0;m [1;32mINFO[0;m ../rspro_client_fsm.c:428 RSPRO_CLIENT(server){REESTABLISH_DELAY}: Destroying existing connection to server [38;5;23m4814 [1;34mDLINP[0;m[38;5;23m [1;34mDEBUG[0;m[38;5;23m stream_cli.c:1068 CLICONN(server,r=127.0.0.10:9998<->l=127.0.0.1:35089){CLOSED} destroy()[0;m [38;5;23m4814 [1;34mDLINP[0;m[38;5;23m [1;34mDEBUG[0;m[38;5;23m stream_cli.c:181 CLICONN(server,r=127.0.0.10:9998<->l=127.0.0.1:35089){CLOSED} close()[0;m [38;5;23m4814 [1;34mDLINP[0;m[38;5;23m [1;34mDEBUG[0;m[38;5;23m stream_cli.c:1075 CLICONN(server,r=127.0.0.10:9998<->l=127.0.0.1:35089){CLOSED} delay free() in_cb_mask=0x02[0;m [38;5;23m4814 [1;34mDLINP[0;m[38;5;23m [1;34mDEBUG[0;m[38;5;23m stream_cli.c:150 CLICONN(server,r=127.0.0.10:9998<->l=127.0.0.1:35089){CLOSED} free(delayed)[0;m RSPRO_SRV0(3)@4a2bd02e722f: Final verdict of PTC: none MTC@4a2bd02e722f: Setting final verdict of the test case. MTC@4a2bd02e722f: Local verdict of MTC: pass MTC@4a2bd02e722f: Local verdict of PTC RSPRO_SRV0(3): none (pass -> pass) MTC@4a2bd02e722f: Test case TC_connectBankReq_timeout finished. Verdict: pass MTC@4a2bd02e722f: Starting external command `https://jenkins.osmocom.org/jenkins/job/ttcn3-remsim-test-asan/ws/ttcn3-tcpdump-stop.sh RemsimBankd_Tests.TC_connectBankReq_timeout pass'. (17:12:45) load average: 0.44, 0.52, 0.60 [1;32m====== RemsimBankd_Tests.TC_connectBankReq_timeout pass ======[0m
Waiting for packet dumper to finish... 0 (prev_count=-1, count=2248) 4814 [1;34mDRSPRO[0;m [1;34mDEBUG[0;m fsm.c:318 RSPRO_CLIENT(server){REESTABLISH_DELAY}: Timeout of T3 4814 [1;34mDRSPRO[0;m [1;34mDEBUG[0;m ../rspro_client_fsm.c:555 RSPRO_CLIENT(server){REESTABLISH_DELAY}: state_chg to REESTABLISH 4814 [1;32mDRSPRO[0;m [1;32mINFO[0;m ../rspro_client_fsm.c:454 RSPRO_CLIENT(server){REESTABLISH}: Creating TCP connection to server at 127.0.0.10:9998 [38;5;23m4814 [1;34mDLINP[0;m[38;5;23m [1;34mDEBUG[0;m[38;5;23m fsm.c:457 IPA-KA(server){INIT}: Allocated[0;m [38;5;23m4814 [1;31mDLINP[0;m[38;5;23m [1;31mERROR[0;m[38;5;23m stream_cli.c:446 CLICONN(server,){CONNECTING} connect failed (-111)[0;m [38;5;23m4814 [1;34mDLINP[0;m[38;5;23m [1;34mDEBUG[0;m[38;5;23m stream_cli.c:181 CLICONN(server,){CONNECTING} close()[0;m 4814 [1;33mDRSPRO[0;m [1;33mNOTICE[0;m ../rspro_client_fsm.c:154 RSPRO_CLIENT(server){REESTABLISH}: RSPRO link to 127.0.0.10:9998 DOWN [38;5;23m4814 [1;32mDLINP[0;m[38;5;23m [1;32mINFO[0;m[38;5;23m ipa_keepalive.c:351 IPA-KA(server){INIT}: Stopping IPA keep-alive FSM[0;m [38;5;23m4814 [1;34mDLINP[0;m[38;5;23m [1;34mDEBUG[0;m[38;5;23m ipa_keepalive.c:352 IPA-KA(server){INIT}: Received Event OSMO_IPA_KA_E_STOP[0;m [38;5;23m4814 [1;34mDLINP[0;m[38;5;23m [1;34mDEBUG[0;m[38;5;23m ipa_keepalive.c:159 IPA-KA(server){INIT}: state_chg to INIT[0;m [38;5;23m4814 [1;34mDLINP[0;m[38;5;23m [1;34mDEBUG[0;m[38;5;23m fsm.c:569 IPA-KA(server){INIT}: Deallocated[0;m 4814 [1;34mDRSPRO[0;m [1;34mDEBUG[0;m ../rspro_client_fsm.c:162 RSPRO_CLIENT(server){REESTABLISH}: Received Event SRVC_E_TCP_DOWN [38;5;23m4814 [1;32mDLINP[0;m[38;5;23m [1;32mINFO[0;m[38;5;23m stream_cli.c:241 CLICONN(server,){CLOSED} not reconnecting, disabled[0;m Waiting for packet dumper to finish... 1 (prev_count=2248, count=3456) MTC@4a2bd02e722f: External command `https://jenkins.osmocom.org/jenkins/job/ttcn3-remsim-test-asan/ws/ttcn3-tcpdump-stop.sh RemsimBankd_Tests.TC_connectBankReq_timeout pass' was executed successfully (exit status: 0). MTC@4a2bd02e722f: Starting external command `https://jenkins.osmocom.org/jenkins/job/ttcn3-remsim-test-asan/ws/ttcn3-tcpdump-start.sh RemsimBankd_Tests.TC_connectBankReq'. ------ RemsimBankd_Tests.TC_connectBankReq ------ (17:12:47) load average: 0.44, 0.52, 0.60 /usr/bin/dumpcap -q -s 1520 -n -i any -w "https://jenkins.osmocom.org/jenkins/job/ttcn3-remsim-test-asan/691/artifact/logs/bankd/testsuite/RemsimBankd_Tests.TC_connectBankReq.pcap" >https://jenkins.osmocom.org/jenkins/job/ttcn3-remsim-test-asan/691/artifact/logs/bankd/testsuite/RemsimBankd_Tests.TC_connectBankReq.pcap.stdout 2>/tmp/cmderr & Waiting for packet dumper to start... 0 MTC@4a2bd02e722f: External command `https://jenkins.osmocom.org/jenkins/job/ttcn3-remsim-test-asan/ws/ttcn3-tcpdump-start.sh RemsimBankd_Tests.TC_connectBankReq' was executed successfully (exit status: 0). MTC@4a2bd02e722f: Test case TC_connectBankReq started. 4814 [1;34mDRSPRO[0;m [1;34mDEBUG[0;m fsm.c:318 RSPRO_CLIENT(server){REESTABLISH}: Timeout of T2 4814 [1;34mDRSPRO[0;m [1;34mDEBUG[0;m ../rspro_client_fsm.c:318 RSPRO_CLIENT(server){REESTABLISH}: state_chg to REESTABLISH_DELAY 4814 [1;32mDRSPRO[0;m [1;32mINFO[0;m ../rspro_client_fsm.c:428 RSPRO_CLIENT(server){REESTABLISH_DELAY}: Destroying existing connection to server [38;5;23m4814 [1;34mDLINP[0;m[38;5;23m [1;34mDEBUG[0;m[38;5;23m stream_cli.c:1068 CLICONN(server,){CLOSED} destroy()[0;m [38;5;23m4814 [1;34mDLINP[0;m[38;5;23m [1;34mDEBUG[0;m[38;5;23m stream_cli.c:181 CLICONN(server,){CLOSED} close()[0;m [38;5;23m4814 [1;34mDLINP[0;m[38;5;23m [1;34mDEBUG[0;m[38;5;23m stream_cli.c:1083 CLICONN(server,){CLOSED} free(destroy)[0;m 4814 [1;34mDRSPRO[0;m [1;34mDEBUG[0;m fsm.c:318 RSPRO_CLIENT(server){REESTABLISH_DELAY}: Timeout of T3 4814 [1;34mDRSPRO[0;m [1;34mDEBUG[0;m ../rspro_client_fsm.c:555 RSPRO_CLIENT(server){REESTABLISH_DELAY}: state_chg to REESTABLISH 4814 [1;32mDRSPRO[0;m [1;32mINFO[0;m ../rspro_client_fsm.c:454 RSPRO_CLIENT(server){REESTABLISH}: Creating TCP connection to server at 127.0.0.10:9998 [38;5;23m4814 [1;34mDLINP[0;m[38;5;23m [1;34mDEBUG[0;m[38;5;23m fsm.c:457 IPA-KA(server){INIT}: Allocated[0;m [38;5;23m4814 [1;32mDLINP[0;m[38;5;23m [1;32mINFO[0;m[38;5;23m stream_cli.c:462 CLICONN(server,r=127.0.0.10:9998<->l=127.0.0.1:45821){CONNECTING} connection established[0;m 4814 [1;33mDRSPRO[0;m [1;33mNOTICE[0;m ../rspro_client_fsm.c:145 RSPRO_CLIENT(server){REESTABLISH}: RSPRO link to 127.0.0.10:9998 UP 4814 [1;34mDRSPRO[0;m [1;34mDEBUG[0;m ../rspro_client_fsm.c:146 RSPRO_CLIENT(server){REESTABLISH}: Received Event SRVC_E_TCP_UP 4814 [1;34mDRSPRO[0;m [1;34mDEBUG[0;m ../rspro_client_fsm.c:513 RSPRO_CLIENT(server){REESTABLISH}: state_chg to ESTABLISHED [38;5;23m4814 [1;32mDLINP[0;m[38;5;23m [1;32mINFO[0;m[38;5;23m ipa_keepalive.c:332 IPA-KA(server){INIT}: Starting IPA keep-alive FSM (interval=30s wait=10s)[0;m [38;5;23m4814 [1;34mDLINP[0;m[38;5;23m [1;34mDEBUG[0;m[38;5;23m ipa_keepalive.c:334 IPA-KA(server){INIT}: Received Event OSMO_IPA_KA_E_START[0;m [38;5;23m4814 [1;34mDLINP[0;m[38;5;23m [1;34mDEBUG[0;m[38;5;23m ipa_keepalive.c:94 IPA-KA(server){INIT}: state_chg to WAIT_RESP[0;m 4814 [1;34mDRSPRO[0;m [1;34mDEBUG[0;m ../rspro_client_fsm.c:100 RSPRO_CLIENT(server){ESTABLISHED}: Tx RSPRO connectBankReq RSPRO_SRV0(4)@4a2bd02e722f: Established a new IPA connection (conn_id=2) RSPRO_SRV0(4)@4a2bd02e722f: CCM Tx:{ msg_type := IPAC_MSGT_ID_GET (4), u := { get := { { len := 1, tag := IPAC_IDTAG_UNITNAME (1) }, { len := 1, tag := IPAC_IDTAG_UNITID (8) } } } } [38;5;23m4814 [1;34mDLINP[0;m[38;5;23m [1;34mDEBUG[0;m[38;5;23m stream_cli.c:573 CLICONN(server,r=127.0.0.10:9998<->l=127.0.0.1:45821){CONNECTED} received 8 bytes from srv[0;m 4814 [1;33mDRSPRO[0;m [1;33mNOTICE[0;m ../rspro_client_fsm.c:199 RSPRO_CLIENT(server){ESTABLISHED}: received ID_GET for unit ID 0/0/0 [38;5;23m4814 [1;32mDLINP[0;m[38;5;23m [1;32mINFO[0;m[38;5;23m ipa.c:396 tag 1: 00-00-00-00-00-00[0;m [38;5;23m4814 [1;32mDLINP[0;m[38;5;23m [1;32mINFO[0;m[38;5;23m ipa.c:396 tag 8: 0/0/0[0;m RSPRO_SRV0(4)@4a2bd02e722f: CCM Rx:{ msg_type := IPAC_MSGT_PING (0), u := omit } RSPRO_SRV0(4)@4a2bd02e722f: CCM Tx:{ msg_type := IPAC_MSGT_PONG (1), u := omit } [38;5;23m4814 [1;34mDLINP[0;m[38;5;23m [1;34mDEBUG[0;m[38;5;23m stream_cli.c:573 CLICONN(server,r=127.0.0.10:9998<->l=127.0.0.1:45821){CONNECTED} received 4 bytes from srv[0;m [38;5;23m4814 [1;34mDLINP[0;m[38;5;23m [1;34mDEBUG[0;m[38;5;23m ipa_keepalive.c:342 IPA-KA(server){WAIT_RESP}: Received Event OSMO_IPA_KA_E_PONG[0;m [38;5;23m4814 [1;34mDLINP[0;m[38;5;23m [1;34mDEBUG[0;m[38;5;23m ipa_keepalive.c:124 IPA-KA(server){WAIT_RESP}: state_chg to IDLE[0;m RSPRO_SRV0(4)@4a2bd02e722f: CCM Rx:{ msg_type := IPAC_MSGT_ID_RESP (5), u := { resp := { { len := 19, tag := IPAC_IDTAG_UNITNAME (1), data := '30302D30302D30302D30302D30302D303000'O }, { len := 7, tag := IPAC_IDTAG_UNITID (8), data := '302F302F3000'O } } } } RSPRO_SRV0(4)@4a2bd02e722f: IPA ID RESP: { { len := 19, tag := IPAC_IDTAG_UNITNAME (1), data := '30302D30302D30302D30302D30302D303000'O }, { len := 7, tag := IPAC_IDTAG_UNITID (8), data := '302F302F3000'O } } MTC@4a2bd02e722f: setverdict(pass): none -> pass reason: ""RemsimBankd_Tests.ttcn:93 : "", new component reason: ""RemsimBankd_Tests.ttcn:93 : "" MTC@4a2bd02e722f: Stopping testcase execution from "RemsimBankd_Tests.ttcn":93 RSPRO_SRV0(4)@4a2bd02e722f: CCM Tx:{ msg_type := IPAC_MSGT_ID_ACK (6), u := omit } RSPRO_SRV0(4)@4a2bd02e722f: CCM Rx:{ msg_type := IPAC_MSGT_ID_ACK (6), u := omit } [38;5;23m4814 [1;34mDLINP[0;m[38;5;23m [1;34mDEBUG[0;m[38;5;23m stream_cli.c:573 CLICONN(server,r=127.0.0.10:9998<->l=127.0.0.1:45821){CONNECTED} received 4 bytes from srv[0;m [38;5;23m4814 [1;33mDLINP[0;m[38;5;23m [1;33mNOTICE[0;m[38;5;23m stream_cli.c:569 CLICONN(server,r=127.0.0.10:9998<->l=127.0.0.1:45821){CONNECTED} connection closed with srv[0;m [38;5;23m4814 [1;34mDLINP[0;m[38;5;23m [1;34mDEBUG[0;m[38;5;23m stream_cli.c:181 CLICONN(server,r=127.0.0.10:9998<->l=127.0.0.1:45821){CONNECTED} close()[0;m 4814 [1;33mDRSPRO[0;m [1;33mNOTICE[0;m ../rspro_client_fsm.c:154 RSPRO_CLIENT(server){ESTABLISHED}: RSPRO link to 127.0.0.10:9998 DOWN [38;5;23m4814 [1;32mDLINP[0;m[38;5;23m [1;32mINFO[0;m[38;5;23m ipa_keepalive.c:351 IPA-KA(server){IDLE}: Stopping IPA keep-alive FSM[0;m [38;5;23m4814 [1;34mDLINP[0;m[38;5;23m [1;34mDEBUG[0;m[38;5;23m ipa_keepalive.c:352 IPA-KA(server){IDLE}: Received Event OSMO_IPA_KA_E_STOP[0;m [38;5;23m4814 [1;34mDLINP[0;m[38;5;23m [1;34mDEBUG[0;m[38;5;23m ipa_keepalive.c:159 IPA-KA(server){IDLE}: state_chg to INIT[0;m [38;5;23m4814 [1;34mDLINP[0;m[38;5;23m [1;34mDEBUG[0;m[38;5;23m fsm.c:569 IPA-KA(server){INIT}: Deallocated[0;m 4814 [1;34mDRSPRO[0;m [1;34mDEBUG[0;m ../rspro_client_fsm.c:162 RSPRO_CLIENT(server){ESTABLISHED}: Received Event SRVC_E_TCP_DOWN 4814 [1;34mDRSPRO[0;m [1;34mDEBUG[0;m ../rspro_client_fsm.c:310 RSPRO_CLIENT(server){ESTABLISHED}: ->REESTABLISH_DELAY delay 986ms; 14ms since last attempt [step 5/123@1s] 4814 [1;34mDRSPRO[0;m [1;34mDEBUG[0;m ../rspro_client_fsm.c:318 RSPRO_CLIENT(server){ESTABLISHED}: state_chg to REESTABLISH_DELAY 4814 [1;32mDRSPRO[0;m [1;32mINFO[0;m ../rspro_client_fsm.c:428 RSPRO_CLIENT(server){REESTABLISH_DELAY}: Destroying existing connection to server [38;5;23m4814 [1;34mDLINP[0;m[38;5;23m [1;34mDEBUG[0;m[38;5;23m stream_cli.c:1068 CLICONN(server,r=127.0.0.10:9998<->l=127.0.0.1:45821){CLOSED} destroy()[0;m [38;5;23m4814 [1;34mDLINP[0;m[38;5;23m [1;34mDEBUG[0;m[38;5;23m stream_cli.c:181 CLICONN(server,r=127.0.0.10:9998<->l=127.0.0.1:45821){CLOSED} close()[0;m [38;5;23m4814 [1;34mDLINP[0;m[38;5;23m [1;34mDEBUG[0;m[38;5;23m stream_cli.c:1075 CLICONN(server,r=127.0.0.10:9998<->l=127.0.0.1:45821){CLOSED} delay free() in_cb_mask=0x02[0;m [38;5;23m4814 [1;34mDLINP[0;m[38;5;23m [1;34mDEBUG[0;m[38;5;23m stream_cli.c:150 CLICONN(server,r=127.0.0.10:9998<->l=127.0.0.1:45821){CLOSED} free(delayed)[0;m RSPRO_SRV0(4)@4a2bd02e722f: Final verdict of PTC: none MTC@4a2bd02e722f: Setting final verdict of the test case. MTC@4a2bd02e722f: Local verdict of MTC: pass reason: ""RemsimBankd_Tests.ttcn:93 : "" MTC@4a2bd02e722f: Local verdict of PTC RSPRO_SRV0(4): none (pass -> pass) MTC@4a2bd02e722f: Test case TC_connectBankReq finished. Verdict: pass reason: "RemsimBankd_Tests.ttcn:93 : " MTC@4a2bd02e722f: Starting external command `https://jenkins.osmocom.org/jenkins/job/ttcn3-remsim-test-asan/ws/ttcn3-tcpdump-stop.sh RemsimBankd_Tests.TC_connectBankReq pass'. (17:12:56) load average: 0.37, 0.51, 0.60 [1;32m====== RemsimBankd_Tests.TC_connectBankReq pass ======[0m
Waiting for packet dumper to finish... 0 (prev_count=-1, count=576) 4814 [1;34mDRSPRO[0;m [1;34mDEBUG[0;m fsm.c:318 RSPRO_CLIENT(server){REESTABLISH_DELAY}: Timeout of T3 4814 [1;34mDRSPRO[0;m [1;34mDEBUG[0;m ../rspro_client_fsm.c:555 RSPRO_CLIENT(server){REESTABLISH_DELAY}: state_chg to REESTABLISH 4814 [1;32mDRSPRO[0;m [1;32mINFO[0;m ../rspro_client_fsm.c:454 RSPRO_CLIENT(server){REESTABLISH}: Creating TCP connection to server at 127.0.0.10:9998 [38;5;23m4814 [1;34mDLINP[0;m[38;5;23m [1;34mDEBUG[0;m[38;5;23m fsm.c:457 IPA-KA(server){INIT}: Allocated[0;m [38;5;23m4814 [1;31mDLINP[0;m[38;5;23m [1;31mERROR[0;m[38;5;23m stream_cli.c:446 CLICONN(server,){CONNECTING} connect failed (-111)[0;m [38;5;23m4814 [1;34mDLINP[0;m[38;5;23m [1;34mDEBUG[0;m[38;5;23m stream_cli.c:181 CLICONN(server,){CONNECTING} close()[0;m 4814 [1;33mDRSPRO[0;m [1;33mNOTICE[0;m ../rspro_client_fsm.c:154 RSPRO_CLIENT(server){REESTABLISH}: RSPRO link to 127.0.0.10:9998 DOWN [38;5;23m4814 [1;32mDLINP[0;m[38;5;23m [1;32mINFO[0;m[38;5;23m ipa_keepalive.c:351 IPA-KA(server){INIT}: Stopping IPA keep-alive FSM[0;m [38;5;23m4814 [1;34mDLINP[0;m[38;5;23m [1;34mDEBUG[0;m[38;5;23m ipa_keepalive.c:352 IPA-KA(server){INIT}: Received Event OSMO_IPA_KA_E_STOP[0;m [38;5;23m4814 [1;34mDLINP[0;m[38;5;23m [1;34mDEBUG[0;m[38;5;23m ipa_keepalive.c:159 IPA-KA(server){INIT}: state_chg to INIT[0;m [38;5;23m4814 [1;34mDLINP[0;m[38;5;23m [1;34mDEBUG[0;m[38;5;23m fsm.c:569 IPA-KA(server){INIT}: Deallocated[0;m 4814 [1;34mDRSPRO[0;m [1;34mDEBUG[0;m ../rspro_client_fsm.c:162 RSPRO_CLIENT(server){REESTABLISH}: Received Event SRVC_E_TCP_DOWN [38;5;23m4814 [1;32mDLINP[0;m[38;5;23m [1;32mINFO[0;m[38;5;23m stream_cli.c:241 CLICONN(server,){CLOSED} not reconnecting, disabled[0;m Waiting for packet dumper to finish... 1 (prev_count=576, count=2340) MTC@4a2bd02e722f: External command `https://jenkins.osmocom.org/jenkins/job/ttcn3-remsim-test-asan/ws/ttcn3-tcpdump-stop.sh RemsimBankd_Tests.TC_connectBankReq pass' was executed successfully (exit status: 0). MTC@4a2bd02e722f: Starting external command `https://jenkins.osmocom.org/jenkins/job/ttcn3-remsim-test-asan/ws/ttcn3-tcpdump-start.sh RemsimBankd_Tests.TC_createMapping'. ------ RemsimBankd_Tests.TC_createMapping ------ (17:12:58) load average: 0.50, 0.53, 0.60 /usr/bin/dumpcap -q -s 1520 -n -i any -w "https://jenkins.osmocom.org/jenkins/job/ttcn3-remsim-test-asan/691/artifact/logs/bankd/testsuite/RemsimBankd_Tests.TC_createMapping.pcap" >https://jenkins.osmocom.org/jenkins/job/ttcn3-remsim-test-asan/691/artifact/logs/bankd/testsuite/RemsimBankd_Tests.TC_createMapping.pcap.stdout 2>/tmp/cmderr & Waiting for packet dumper to start... 0 MTC@4a2bd02e722f: External command `https://jenkins.osmocom.org/jenkins/job/ttcn3-remsim-test-asan/ws/ttcn3-tcpdump-start.sh RemsimBankd_Tests.TC_createMapping' was executed successfully (exit status: 0). MTC@4a2bd02e722f: Test case TC_createMapping started. 4814 [1;34mDRSPRO[0;m [1;34mDEBUG[0;m fsm.c:318 RSPRO_CLIENT(server){REESTABLISH}: Timeout of T2 4814 [1;34mDRSPRO[0;m [1;34mDEBUG[0;m ../rspro_client_fsm.c:318 RSPRO_CLIENT(server){REESTABLISH}: state_chg to REESTABLISH_DELAY 4814 [1;32mDRSPRO[0;m [1;32mINFO[0;m ../rspro_client_fsm.c:428 RSPRO_CLIENT(server){REESTABLISH_DELAY}: Destroying existing connection to server [38;5;23m4814 [1;34mDLINP[0;m[38;5;23m [1;34mDEBUG[0;m[38;5;23m stream_cli.c:1068 CLICONN(server,){CLOSED} destroy()[0;m [38;5;23m4814 [1;34mDLINP[0;m[38;5;23m [1;34mDEBUG[0;m[38;5;23m stream_cli.c:181 CLICONN(server,){CLOSED} close()[0;m [38;5;23m4814 [1;34mDLINP[0;m[38;5;23m [1;34mDEBUG[0;m[38;5;23m stream_cli.c:1083 CLICONN(server,){CLOSED} free(destroy)[0;m 4814 [1;34mDRSPRO[0;m [1;34mDEBUG[0;m fsm.c:318 RSPRO_CLIENT(server){REESTABLISH_DELAY}: Timeout of T3 4814 [1;34mDRSPRO[0;m [1;34mDEBUG[0;m ../rspro_client_fsm.c:555 RSPRO_CLIENT(server){REESTABLISH_DELAY}: state_chg to REESTABLISH 4814 [1;32mDRSPRO[0;m [1;32mINFO[0;m ../rspro_client_fsm.c:454 RSPRO_CLIENT(server){REESTABLISH}: Creating TCP connection to server at 127.0.0.10:9998 [38;5;23m4814 [1;34mDLINP[0;m[38;5;23m [1;34mDEBUG[0;m[38;5;23m fsm.c:457 IPA-KA(server){INIT}: Allocated[0;m [38;5;23m4814 [1;32mDLINP[0;m[38;5;23m [1;32mINFO[0;m[38;5;23m stream_cli.c:462 CLICONN(server,r=127.0.0.10:9998<->l=127.0.0.1:41811){CONNECTING} connection established[0;m 4814 [1;33mDRSPRO[0;m [1;33mNOTICE[0;m ../rspro_client_fsm.c:145 RSPRO_CLIENT(server){REESTABLISH}: RSPRO link to 127.0.0.10:9998 UP 4814 [1;34mDRSPRO[0;m [1;34mDEBUG[0;m ../rspro_client_fsm.c:146 RSPRO_CLIENT(server){REESTABLISH}: Received Event SRVC_E_TCP_UP 4814 [1;34mDRSPRO[0;m [1;34mDEBUG[0;m ../rspro_client_fsm.c:513 RSPRO_CLIENT(server){REESTABLISH}: state_chg to ESTABLISHED [38;5;23m4814 [1;32mDLINP[0;m[38;5;23m [1;32mINFO[0;m[38;5;23m ipa_keepalive.c:332 IPA-KA(server){INIT}: Starting IPA keep-alive FSM (interval=30s wait=10s)[0;m [38;5;23m4814 [1;34mDLINP[0;m[38;5;23m [1;34mDEBUG[0;m[38;5;23m ipa_keepalive.c:334 IPA-KA(server){INIT}: Received Event OSMO_IPA_KA_E_START[0;m [38;5;23m4814 [1;34mDLINP[0;m[38;5;23m [1;34mDEBUG[0;m[38;5;23m ipa_keepalive.c:94 IPA-KA(server){INIT}: state_chg to WAIT_RESP[0;m 4814 [1;34mDRSPRO[0;m [1;34mDEBUG[0;m ../rspro_client_fsm.c:100 RSPRO_CLIENT(server){ESTABLISHED}: Tx RSPRO connectBankReq RSPRO_SRV0(5)@4a2bd02e722f: Established a new IPA connection (conn_id=2) RSPRO_SRV0(5)@4a2bd02e722f: CCM Tx:{ msg_type := IPAC_MSGT_ID_GET (4), u := { get := { { len := 1, tag := IPAC_IDTAG_UNITNAME (1) }, { len := 1, tag := IPAC_IDTAG_UNITID (8) } } } } [38;5;23m4814 [1;34mDLINP[0;m[38;5;23m [1;34mDEBUG[0;m[38;5;23m stream_cli.c:573 CLICONN(server,r=127.0.0.10:9998<->l=127.0.0.1:41811){CONNECTED} received 8 bytes from srv[0;m 4814 [1;33mDRSPRO[0;m [1;33mNOTICE[0;m ../rspro_client_fsm.c:199 RSPRO_CLIENT(server){ESTABLISHED}: received ID_GET for unit ID 0/0/0 [38;5;23m4814 [1;32mDLINP[0;m[38;5;23m [1;32mINFO[0;m[38;5;23m ipa.c:396 tag 1: 00-00-00-00-00-00[0;m [38;5;23m4814 [1;32mDLINP[0;m[38;5;23m [1;32mINFO[0;m[38;5;23m ipa.c:396 tag 8: 0/0/0[0;m RSPRO_SRV0(5)@4a2bd02e722f: CCM Rx:{ msg_type := IPAC_MSGT_PING (0), u := omit } RSPRO_SRV0(5)@4a2bd02e722f: CCM Tx:{ msg_type := IPAC_MSGT_PONG (1), u := omit } [38;5;23m4814 [1;34mDLINP[0;m[38;5;23m [1;34mDEBUG[0;m[38;5;23m stream_cli.c:573 CLICONN(server,r=127.0.0.10:9998<->l=127.0.0.1:41811){CONNECTED} received 4 bytes from srv[0;m [38;5;23m4814 [1;34mDLINP[0;m[38;5;23m [1;34mDEBUG[0;m[38;5;23m ipa_keepalive.c:342 IPA-KA(server){WAIT_RESP}: Received Event OSMO_IPA_KA_E_PONG[0;m [38;5;23m4814 [1;34mDLINP[0;m[38;5;23m [1;34mDEBUG[0;m[38;5;23m ipa_keepalive.c:124 IPA-KA(server){WAIT_RESP}: state_chg to IDLE[0;m RSPRO_SRV0(5)@4a2bd02e722f: CCM Rx:{ msg_type := IPAC_MSGT_ID_RESP (5), u := { resp := { { len := 19, tag := IPAC_IDTAG_UNITNAME (1), data := '30302D30302D30302D30302D30302D303000'O }, { len := 7, tag := IPAC_IDTAG_UNITID (8), data := '302F302F3000'O } } } } RSPRO_SRV0(5)@4a2bd02e722f: IPA ID RESP: { { len := 19, tag := IPAC_IDTAG_UNITNAME (1), data := '30302D30302D30302D30302D30302D303000'O }, { len := 7, tag := IPAC_IDTAG_UNITID (8), data := '302F302F3000'O } } RSPRO_SRV0(5)@4a2bd02e722f: CCM Tx:{ msg_type := IPAC_MSGT_ID_ACK (6), u := omit } RSPRO_SRV0(5)@4a2bd02e722f: CCM Rx:{ msg_type := IPAC_MSGT_ID_ACK (6), u := omit } [38;5;23m4814 [1;34mDLINP[0;m[38;5;23m [1;34mDEBUG[0;m[38;5;23m stream_cli.c:573 CLICONN(server,r=127.0.0.10:9998<->l=127.0.0.1:41811){CONNECTED} received 79 bytes from srv[0;m [38;5;23m4814 [1;34mDLINP[0;m[38;5;23m [1;34mDEBUG[0;m[38;5;23m stream_cli.c:573 CLICONN(server,r=127.0.0.10:9998<->l=127.0.0.1:41811){CONNECTED} received 79 bytes from srv[0;m 4814 [1;34mDRSPRO[0;m [1;34mDEBUG[0;m ../rspro_client_fsm.c:255 RSPRO_CLIENT(server){ESTABLISHED}: Received RSPRO (L1=data-4) [L2]> 30 35 80 01 02 81 01 00 a2 2d a1 2b 30 26 0a 01 01 16 0b 74 74 63 6e 2d 73 65 72 76 65 72 80 05 54 54 43 4e 33 81 03 30 2e 31 82 08 73 79 73 6d 6f 63 6f 6d 0a 01 00 4814 [1;34mDRSPRO[0;m [1;34mDEBUG[0;m rspro_util.c:86 decoding (L1=data-4) [L2]> 30 35 80 01 02 81 01 00 a2 2d a1 2b 30 26 0a 01 01 16 0b 74 74 63 6e 2d 73 65 72 76 65 72 80 05 54 54 43 4e 33 81 03 30 2e 31 82 08 73 79 73 6d 6f 63 6f 6d 0a 01 00 4814 [1;34mDRSPRO[0;m [1;34mDEBUG[0;m bankd_main.c:182 RSPRO_CLIENT(server){ESTABLISHED}: Rx RSPRO connectBankRes 4814 [1;34mDRSPRO[0;m [1;34mDEBUG[0;m bankd_main.c:195 RSPRO_CLIENT(server){ESTABLISHED}: Received Event SRVC_E_CLIENT_CONN_RES 4814 [1;34mDRSPRO[0;m [1;34mDEBUG[0;m ../rspro_client_fsm.c:365 RSPRO_CLIENT(server){ESTABLISHED}: state_chg to CONNECTED [38;5;23m4814 [1;34mDLINP[0;m[38;5;23m [1;34mDEBUG[0;m[38;5;23m stream_cli.c:573 CLICONN(server,r=127.0.0.10:9998<->l=127.0.0.1:41811){CONNECTED} received 79 bytes from srv[0;m 4814 [1;34mDRSPRO[0;m [1;34mDEBUG[0;m ../rspro_client_fsm.c:255 RSPRO_CLIENT(server){CONNECTED}: Received RSPRO (L1=data-4) [L2]> 30 0a 80 01 02 81 01 00 a2 02 b3 00 4814 [1;34mDRSPRO[0;m [1;34mDEBUG[0;m rspro_util.c:86 decoding (L1=data-4) [L2]> 30 0a 80 01 02 81 01 00 a2 02 b3 00 4814 [1;34mDRSPRO[0;m [1;34mDEBUG[0;m bankd_main.c:182 RSPRO_CLIENT(server){CONNECTED}: Rx RSPRO resetStateReq 4814 [1;34mDRSPRO[0;m [1;34mDEBUG[0;m ../rspro_client_fsm.c:111 RSPRO_CLIENT(server){CONNECTED}: Received Event SRVC_E_RSPRO_TX 4814 [1;34mDRSPRO[0;m [1;34mDEBUG[0;m ../rspro_client_fsm.c:100 RSPRO_CLIENT(server){CONNECTED}: Tx RSPRO resetStateRes MTC@4a2bd02e722f: setverdict(pass): none -> pass [38;5;23m4814 [1;34mDLINP[0;m[38;5;23m [1;34mDEBUG[0;m[38;5;23m stream_cli.c:573 CLICONN(server,r=127.0.0.10:9998<->l=127.0.0.1:41811){CONNECTED} received 32 bytes from srv[0;m 4814 [1;34mDRSPRO[0;m [1;34mDEBUG[0;m ../rspro_client_fsm.c:255 RSPRO_CLIENT(server){CONNECTED}: Received RSPRO (L1=data-4) [L2]> 30 1a 80 01 02 81 01 00 a2 12 a4 10 30 06 02 01 17 02 01 2a 30 06 02 01 01 02 01 00 4814 [1;34mDRSPRO[0;m [1;34mDEBUG[0;m rspro_util.c:86 decoding (L1=data-4) [L2]> 30 1a 80 01 02 81 01 00 a2 12 a4 10 30 06 02 01 17 02 01 2a 30 06 02 01 01 02 01 00 4814 [1;34mDRSPRO[0;m [1;34mDEBUG[0;m bankd_main.c:182 RSPRO_CLIENT(server){CONNECTED}: Rx RSPRO createMappingReq 4814 [1;32mDSLOTMAP[0;m [1;32mINFO[0;m ../slotmap.c:131 Slot Map B(1:0) <-> C(23:42) added 4814 [1;34mDRSPRO[0;m [1;34mDEBUG[0;m ../rspro_client_fsm.c:111 RSPRO_CLIENT(server){CONNECTED}: Received Event SRVC_E_RSPRO_TX 4814 [1;34mDRSPRO[0;m [1;34mDEBUG[0;m ../rspro_client_fsm.c:100 RSPRO_CLIENT(server){CONNECTED}: Tx RSPRO createMappingRes MTC@4a2bd02e722f: setverdict(pass): pass -> pass, component reason not changed MTC@4a2bd02e722f: setverdict(pass): pass -> pass reason: ""RemsimBankd_Tests.ttcn:104 : "", component reason not changed MTC@4a2bd02e722f: Stopping testcase execution from "RemsimBankd_Tests.ttcn":104 [38;5;23m4814 [1;33mDLINP[0;m[38;5;23m [1;33mNOTICE[0;m[38;5;23m stream_cli.c:569 CLICONN(server,r=127.0.0.10:9998<->l=127.0.0.1:41811){CONNECTED} connection closed with srv[0;m [38;5;23m4814 [1;34mDLINP[0;m[38;5;23m [1;34mDEBUG[0;m[38;5;23m stream_cli.c:181 CLICONN(server,r=127.0.0.10:9998<->l=127.0.0.1:41811){CONNECTED} close()[0;m 4814 [1;33mDRSPRO[0;m [1;33mNOTICE[0;m ../rspro_client_fsm.c:154 RSPRO_CLIENT(server){CONNECTED}: RSPRO link to 127.0.0.10:9998 DOWN [38;5;23m4814 [1;32mDLINP[0;m[38;5;23m [1;32mINFO[0;m[38;5;23m ipa_keepalive.c:351 IPA-KA(server){IDLE}: Stopping IPA keep-alive FSM[0;m [38;5;23m4814 [1;34mDLINP[0;m[38;5;23m [1;34mDEBUG[0;m[38;5;23m ipa_keepalive.c:352 IPA-KA(server){IDLE}: Received Event OSMO_IPA_KA_E_STOP[0;m [38;5;23m4814 [1;34mDLINP[0;m[38;5;23m [1;34mDEBUG[0;m[38;5;23m ipa_keepalive.c:159 IPA-KA(server){IDLE}: state_chg to INIT[0;m [38;5;23m4814 [1;34mDLINP[0;m[38;5;23m [1;34mDEBUG[0;m[38;5;23m fsm.c:569 IPA-KA(server){INIT}: Deallocated[0;m 4814 [1;34mDRSPRO[0;m [1;34mDEBUG[0;m ../rspro_client_fsm.c:162 RSPRO_CLIENT(server){CONNECTED}: Received Event SRVC_E_TCP_DOWN 4814 [1;34mDRSPRO[0;m [1;34mDEBUG[0;m ../rspro_client_fsm.c:310 RSPRO_CLIENT(server){CONNECTED}: ->REESTABLISH_DELAY delay 938ms; 62ms since last attempt [step 7/123@1s] 4814 [1;34mDRSPRO[0;m [1;34mDEBUG[0;m ../rspro_client_fsm.c:318 RSPRO_CLIENT(server){CONNECTED}: state_chg to REESTABLISH_DELAY 4814 [1;32mDRSPRO[0;m [1;32mINFO[0;m ../rspro_client_fsm.c:428 RSPRO_CLIENT(server){REESTABLISH_DELAY}: Destroying existing connection to server [38;5;23m4814 [1;34mDLINP[0;m[38;5;23m [1;34mDEBUG[0;m[38;5;23m stream_cli.c:1068 CLICONN(server,r=127.0.0.10:9998<->l=127.0.0.1:41811){CLOSED} destroy()[0;m [38;5;23m4814 [1;34mDLINP[0;m[38;5;23m [1;34mDEBUG[0;m[38;5;23m stream_cli.c:181 CLICONN(server,r=127.0.0.10:9998<->l=127.0.0.1:41811){CLOSED} close()[0;m [38;5;23m4814 [1;34mDLINP[0;m[38;5;23m [1;34mDEBUG[0;m[38;5;23m stream_cli.c:1075 CLICONN(server,r=127.0.0.10:9998<->l=127.0.0.1:41811){CLOSED} delay free() in_cb_mask=0x02[0;m [38;5;23m4814 [1;34mDLINP[0;m[38;5;23m [1;34mDEBUG[0;m[38;5;23m stream_cli.c:150 CLICONN(server,r=127.0.0.10:9998<->l=127.0.0.1:41811){CLOSED} free(delayed)[0;m RSPRO_SRV0(5)@4a2bd02e722f: Final verdict of PTC: none MTC@4a2bd02e722f: Setting final verdict of the test case. MTC@4a2bd02e722f: Local verdict of MTC: pass MTC@4a2bd02e722f: Local verdict of PTC RSPRO_SRV0(5): none (pass -> pass) MTC@4a2bd02e722f: Test case TC_createMapping finished. Verdict: pass MTC@4a2bd02e722f: Starting external command `https://jenkins.osmocom.org/jenkins/job/ttcn3-remsim-test-asan/ws/ttcn3-tcpdump-stop.sh RemsimBankd_Tests.TC_createMapping pass'. (17:13:07) load average: 1.10, 0.66, 0.64 [1;32m====== RemsimBankd_Tests.TC_createMapping pass ======[0m
Waiting for packet dumper to finish... 0 (prev_count=-1, count=576) 4814 [1;34mDRSPRO[0;m [1;34mDEBUG[0;m fsm.c:318 RSPRO_CLIENT(server){REESTABLISH_DELAY}: Timeout of T3 4814 [1;34mDRSPRO[0;m [1;34mDEBUG[0;m ../rspro_client_fsm.c:555 RSPRO_CLIENT(server){REESTABLISH_DELAY}: state_chg to REESTABLISH 4814 [1;32mDRSPRO[0;m [1;32mINFO[0;m ../rspro_client_fsm.c:454 RSPRO_CLIENT(server){REESTABLISH}: Creating TCP connection to server at 127.0.0.10:9998 [38;5;23m4814 [1;34mDLINP[0;m[38;5;23m [1;34mDEBUG[0;m[38;5;23m fsm.c:457 IPA-KA(server){INIT}: Allocated[0;m [38;5;23m4814 [1;31mDLINP[0;m[38;5;23m [1;31mERROR[0;m[38;5;23m stream_cli.c:446 CLICONN(server,){CONNECTING} connect failed (-111)[0;m [38;5;23m4814 [1;34mDLINP[0;m[38;5;23m [1;34mDEBUG[0;m[38;5;23m stream_cli.c:181 CLICONN(server,){CONNECTING} close()[0;m 4814 [1;33mDRSPRO[0;m [1;33mNOTICE[0;m ../rspro_client_fsm.c:154 RSPRO_CLIENT(server){REESTABLISH}: RSPRO link to 127.0.0.10:9998 DOWN [38;5;23m4814 [1;32mDLINP[0;m[38;5;23m [1;32mINFO[0;m[38;5;23m ipa_keepalive.c:351 IPA-KA(server){INIT}: Stopping IPA keep-alive FSM[0;m [38;5;23m4814 [1;34mDLINP[0;m[38;5;23m [1;34mDEBUG[0;m[38;5;23m ipa_keepalive.c:352 IPA-KA(server){INIT}: Received Event OSMO_IPA_KA_E_STOP[0;m [38;5;23m4814 [1;34mDLINP[0;m[38;5;23m [1;34mDEBUG[0;m[38;5;23m ipa_keepalive.c:159 IPA-KA(server){INIT}: state_chg to INIT[0;m [38;5;23m4814 [1;34mDLINP[0;m[38;5;23m [1;34mDEBUG[0;m[38;5;23m fsm.c:569 IPA-KA(server){INIT}: Deallocated[0;m 4814 [1;34mDRSPRO[0;m [1;34mDEBUG[0;m ../rspro_client_fsm.c:162 RSPRO_CLIENT(server){REESTABLISH}: Received Event SRVC_E_TCP_DOWN [38;5;23m4814 [1;32mDLINP[0;m[38;5;23m [1;32mINFO[0;m[38;5;23m stream_cli.c:241 CLICONN(server,){CLOSED} not reconnecting, disabled[0;m Waiting for packet dumper to finish... 1 (prev_count=576, count=2988) MTC@4a2bd02e722f: External command `https://jenkins.osmocom.org/jenkins/job/ttcn3-remsim-test-asan/ws/ttcn3-tcpdump-stop.sh RemsimBankd_Tests.TC_createMapping pass' was executed successfully (exit status: 0). MTC@4a2bd02e722f: Starting external command `https://jenkins.osmocom.org/jenkins/job/ttcn3-remsim-test-asan/ws/ttcn3-tcpdump-start.sh RemsimBankd_Tests.TC_createMapping_busySlot'. ------ RemsimBankd_Tests.TC_createMapping_busySlot ------ (17:13:09) load average: 1.02, 0.64, 0.64 /usr/bin/dumpcap -q -s 1520 -n -i any -w "https://jenkins.osmocom.org/jenkins/job/ttcn3-remsim-test-asan/691/artifact/logs/bankd/testsuite/RemsimBankd_Tests.TC_createMapping_busySlot.pcap" >https://jenkins.osmocom.org/jenkins/job/ttcn3-remsim-test-asan/691/artifact/logs/bankd/testsuite/RemsimBankd_Tests.TC_createMapping_busySlot.pcap.stdout 2>/tmp/cmderr & Waiting for packet dumper to start... 0 [1;34m[testenv][bankd] Stopping podman container[0m [0;94m[testenv][bankd] + ['podman', 'kill', 'testenv-remsim-all-osmocom-nightly-asan-20260427-1712-b0485ce5-0'][0m testenv-remsim-all-osmocom-nightly-asan-20260427-1712-b0485ce5-0 [1;34m[testenv][bankd] Stopping testsuite (3303231)[0m [0;94m[testenv] feed_watchdog_loop: podman container has stopped[0m [1;34m[testenv][bankd] Logs saved to: https://jenkins.osmocom.org/jenkins/job/ttcn3-remsim-test-asan/691/artifact/... [0m + RC=1 + [ 1 = 0 ] + uptime + grep --color=always -o load.* [01;31m[Kload average: 1.02, 0.64, 0.64[m[K + exit 1 Build step 'Execute shell' marked build as failure Recording test results [Checks API] No suitable checks publisher found.
jenkins-notifications@lists.osmocom.org