Build failed in Jenkins: ttcn3-s1gw-test #474

See https://jenkins.osmocom.org/jenkins/job/ttcn3-s1gw-test/474/display/redirect?page=changes

Changes:

[Oliver Smith] buildsystem/gen_links: catch broken symlinks

------------------------------------------ [...truncated 68.14 KiB...] 2025-09-25T09:03:14.437064+00:00 [info] <0.469.0> Supervisor: {local,kernel_sup}. Started: id=rex,pid=<0.480.0>. (supervisor:report_progress/3:2135) 2025-09-25T09:03:14.437102+00:00 [info] <0.469.0> Supervisor: {local,kernel_sup}. Started: id=global_name_server,pid=<0.482.0>. (supervisor:report_progress/3:2135) 2025-09-25T09:03:14.437132+00:00 [info] <0.485.0> Supervisor: {local,net_sup}. Started: id=erl_epmd,pid=<0.486.0>. (supervisor:report_progress/3:2135) 2025-09-25T09:03:14.437140+00:00 [info] <0.485.0> Supervisor: {local,net_sup}. Started: id=auth,pid=<0.487.0>. (supervisor:report_progress/3:2135) 2025-09-25T09:03:14.437381+00:00 [info] <0.485.0> Supervisor: {local,net_sup}. Started: id=net_kernel,pid=<0.488.0>. (supervisor:report_progress/3:2135) 2025-09-25T09:03:14.437394+00:00 [info] <0.469.0> Supervisor: {local,kernel_sup}. Started: id=net_sup,pid=<0.485.0>. (supervisor:report_progress/3:2135) 2025-09-25T09:03:14.437408+00:00 [info] <0.469.0> Supervisor: {local,kernel_sup}. Started: id=global_group,pid=<0.491.0>. (supervisor:report_progress/3:2135) 2025-09-25T09:03:14.437418+00:00 [info] <0.469.0> Supervisor: {local,kernel_sup}. Started: id=erl_signal_server,pid=<0.493.0>. (supervisor:report_progress/3:2135) 2025-09-25T09:03:14.437473+00:00 [info] <0.494.0> Supervisor: {<0.494.0>,user_sup}. Started: pid=<0.497.0>,mfa={user_sup,init,[[]]}. (supervisor_bridge:report_progress/4:239) 2025-09-25T09:03:14.437487+00:00 [info] <0.469.0> Supervisor: {local,kernel_sup}. Started: id=user,pid=<0.494.0>. (supervisor:report_progress/3:2135) 2025-09-25T09:03:14.437502+00:00 [info] <0.498.0> Supervisor: {local,logger_sup}. Started: id=logger_handler_watcher,pid=<0.499.0>. (supervisor:report_progress/3:2135) 2025-09-25T09:03:14.437531+00:00 [info] <0.498.0> Supervisor: {local,logger_sup}. Started: id=logger_proxy,pid=<0.500.0>. (supervisor:report_progress/3:2135) 2025-09-25T09:03:14.437537+00:00 [info] <0.469.0> Supervisor: {local,kernel_sup}. Started: id=logger_sup,pid=<0.498.0>. (supervisor:report_progress/3:2135) 2025-09-25T09:03:14.437552+00:00 [info] <0.469.0> Supervisor: {local,kernel_sup}. Started: id=kernel_config,pid=<0.501.0>. (supervisor:report_progress/3:2135) 2025-09-25T09:03:14.437767+00:00 [info] <0.464.0> Simple handler buffer full, dropped 3 messages 2025-09-25T09:03:14.438948+00:00 [info] <0.465.0> Application: kernel. Started at: 'osmo-s1gw@9897b8b3263e'. (application_controller:info_started/2:2113) 2025-09-25T09:03:14.438993+00:00 [info] <0.465.0> Application: stdlib. Started at: 'osmo-s1gw@9897b8b3263e'. (application_controller:info_started/2:2113) 2025-09-25T09:03:14.439038+00:00 [info] <0.465.0> Application: logger_color_formatter. Started at: 'osmo-s1gw@9897b8b3263e'. (application_controller:info_started/2:2113) 2025-09-25T09:03:14.439070+00:00 [info] <0.465.0> Application: logger_gsmtap. Started at: 'osmo-s1gw@9897b8b3263e'. (application_controller:info_started/2:2113) 2025-09-25T09:03:14.439108+00:00 [info] <0.465.0> Application: pfcplib. Started at: 'osmo-s1gw@9897b8b3263e'. (application_controller:info_started/2:2113) 2025-09-25T09:03:14.439136+00:00 [info] <0.465.0> Application: xmerl. Started at: 'osmo-s1gw@9897b8b3263e'. (application_controller:info_started/2:2113) 2025-09-25T09:03:14.439168+00:00 [info] <0.465.0> Application: jiffy. Started at: 'osmo-s1gw@9897b8b3263e'. (application_controller:info_started/2:2113) 2025-09-25T09:03:14.439199+00:00 [info] <0.465.0> Application: enftables. Started at: 'osmo-s1gw@9897b8b3263e'. (application_controller:info_started/2:2113) 2025-09-25T09:03:14.439256+00:00 [info] <0.510.0> Supervisor: {local,setup_sup}. Started: id=setup_srv,pid=<0.511.0>. (supervisor:report_progress/3:2135) 2025-09-25T09:03:14.439319+00:00 [notice] <0.511.0> Setup running ... 2025-09-25T09:03:14.439662+00:00 [notice] <0.511.0> Directories verified. Res = ok 2025-09-25T09:03:14.439730+00:00 [notice] <0.511.0> Setup finished processing hooks (Mode=normal)... 2025-09-25T09:03:14.439765+00:00 [info] <0.465.0> Application: setup. Started at: 'osmo-s1gw@9897b8b3263e'. (application_controller:info_started/2:2113) 2025-09-25T09:03:14.439801+00:00 [info] <0.465.0> Application: syntax_tools. Started at: 'osmo-s1gw@9897b8b3263e'. (application_controller:info_started/2:2113) 2025-09-25T09:03:14.439830+00:00 [info] <0.465.0> Application: parse_trans. Started at: 'osmo-s1gw@9897b8b3263e'. (application_controller:info_started/2:2113) 2025-09-25T09:03:14.440333+00:00 [info] <0.514.0> Supervisor: {local,exometer_core_sup}. Started: id=exometer_admin,pid=<0.515.0>. (supervisor:report_progress/3:2135) 2025-09-25T09:03:14.440421+00:00 [info] <0.514.0> Supervisor: {local,exometer_core_sup}. Started: id=exometer_cache,pid=<0.516.0>. (supervisor:report_progress/3:2135) 2025-09-25T09:03:14.440462+00:00 [info] <0.514.0> Supervisor: {local,exometer_core_sup}. Started: id=exometer_report,pid=<0.517.0>. (supervisor:report_progress/3:2135) 2025-09-25T09:03:14.440497+00:00 [info] <0.514.0> Supervisor: {local,exometer_core_sup}. Started: id=exometer_report_logger_sup,pid=<0.518.0>. (supervisor:report_progress/3:2135) 2025-09-25T09:03:14.440543+00:00 [info] <0.514.0> Supervisor: {local,exometer_core_sup}. Started: id=exometer_alias,pid=<0.519.0>. (supervisor:report_progress/3:2135) 2025-09-25T09:03:14.440673+00:00 [info] <0.517.0> Starting reporters with [{reporters,[{exometer_report_statsd,[{hostname,"127.0.4.10"},{port,8125},{prefix,"s1gw"},{type_map,[]}]}]},{subscribers,[{select,{[{{['_'|'_'],counter,'_'},[],['$_']}],exometer_report_statsd,value,1000,true,[{report_type,counter}]}},{select,{[{{['_'|'_'],gauge,'_'},[],['$_']}],exometer_report_statsd,value,1000,true,[{report_type,gauge}]}}]}] (exometer_report:do_start_reporters/1:695) 2025-09-25T09:03:14.440802+00:00 [info] <0.520.0> exometer_report_statsd([{hostname,"127.0.4.10"},{port,8125},{prefix,"s1gw"},{type_map,[]}]): Starting (exometer_report_statsd:exometer_init/1:49) 2025-09-25T09:03:14.440847+00:00 [info] <0.465.0> Application: exometer_core. Started at: 'osmo-s1gw@9897b8b3263e'. (application_controller:info_started/2:2113) 2025-09-25T09:03:14.440903+00:00 [info] <0.465.0> Application: exometer_report_statsd. Started at: 'osmo-s1gw@9897b8b3263e'. (application_controller:info_started/2:2113) 2025-09-25T09:03:14.440876+00:00 [info] <0.521.0> Supervisor: {local,inet_gethost_native_sup}. Started: pid=<0.522.0>,mfa={inet_gethost_native,init,[[]]}. (supervisor_bridge:report_progress/4:239) 2025-09-25T09:03:14.440948+00:00 [info] <0.465.0> Application: compiler. Started at: 'osmo-s1gw@9897b8b3263e'. (application_controller:info_started/2:2113) 2025-09-25T09:03:14.440972+00:00 [debug] <0.503.0> Supervisor: {local,kernel_safe_sup}. Started: id=inet_gethost_native_sup,pid=<0.521.0>. (supervisor:report_progress/3:2145) 2025-09-25T09:03:14.440988+00:00 [info] <0.465.0> Application: elli. Started at: 'osmo-s1gw@9897b8b3263e'. (application_controller:info_started/2:2113) 2025-09-25T09:03:14.441033+00:00 [info] <0.465.0> Application: njson. Started at: 'osmo-s1gw@9897b8b3263e'. (application_controller:info_started/2:2113) 2025-09-25T09:03:14.441073+00:00 [info] <0.465.0> Application: ndto. Started at: 'osmo-s1gw@9897b8b3263e'. (application_controller:info_started/2:2113) 2025-09-25T09:03:14.441109+00:00 [info] <0.465.0> Application: erf. Started at: 'osmo-s1gw@9897b8b3263e'. (application_controller:info_started/2:2113) 2025-09-25T09:03:14.441178+00:00 [info] <0.525.0> Initiating metrics (s1gw_metrics:init/0:129) 2025-09-25T09:03:14.441295+00:00 [debug] <0.517.0> subscribe_(exometer_report_statsd, [ctr,pfcp,heartbeat_req,tx], value, 1000, true, [{report_type,counter}], enabled) (exometer_report:subscribe_/7:1492) 2025-09-25T09:03:14.441397+00:00 [debug] <0.517.0> subscribe_(exometer_report_statsd, [ctr,pfcp,heartbeat_req,rx], value, 1000, true, [{report_type,counter}], enabled) (exometer_report:subscribe_/7:1492) 2025-09-25T09:03:14.441431+00:00 [debug] <0.517.0> subscribe_(exometer_report_statsd, [ctr,pfcp,heartbeat_req,timeout], value, 1000, true, [{report_type,counter}], enabled) (exometer_report:subscribe_/7:1492) 2025-09-25T09:03:14.441477+00:00 [debug] <0.517.0> subscribe_(exometer_report_statsd, [ctr,pfcp,heartbeat_resp,rx], value, 1000, true, [{report_type,counter}], enabled) (exometer_report:subscribe_/7:1492) 2025-09-25T09:03:14.441567+00:00 [debug] <0.517.0> subscribe_(exometer_report_statsd, [ctr,pfcp,assoc_setup_req,timeout], value, 1000, true, [{report_type,counter}], enabled) (exometer_report:subscribe_/7:1492) 2025-09-25T09:03:14.441604+00:00 [debug] <0.517.0> subscribe_(exometer_report_statsd, [ctr,pfcp,assoc_setup_req,tx], value, 1000, true, [{report_type,counter}], enabled) (exometer_report:subscribe_/7:1492) 2025-09-25T09:03:14.441692+00:00 [debug] <0.517.0> subscribe_(exometer_report_statsd, [ctr,pfcp,assoc_setup_resp,rx], value, 1000, true, [{report_type,counter}], enabled) (exometer_report:subscribe_/7:1492) 2025-09-25T09:03:14.441738+00:00 [debug] <0.517.0> subscribe_(exometer_report_statsd, [ctr,pfcp,assoc_setup_resp,rx_ack], value, 1000, true, [{report_type,counter}], enabled) (exometer_report:subscribe_/7:1492) 2025-09-25T09:03:14.441773+00:00 [debug] <0.517.0> subscribe_(exometer_report_statsd, [ctr,pfcp,assoc_setup_resp,rx_nack], value, 1000, true, [{report_type,counter}], enabled) (exometer_report:subscribe_/7:1492) 2025-09-25T09:03:14.441807+00:00 [info] <0.525.0> Supervisor: {local,osmo_s1gw_sup}. Started: id=enb_registry,pid=<0.526.0>. (supervisor:report_progress/3:2135) 2025-09-25T09:03:14.441824+00:00 [debug] <0.517.0> subscribe_(exometer_report_statsd, [ctr,pfcp,heartbeat_resp,tx], value, 1000, true, [{report_type,counter}], enabled) (exometer_report:subscribe_/7:1492) 2025-09-25T09:03:14.441865+00:00 [debug] <0.517.0> subscribe_(exometer_report_statsd, [ctr,pfcp,unexpected_pdu], value, 1000, true, [{report_type,counter}], enabled) (exometer_report:subscribe_/7:1492) 2025-09-25T09:03:14.441930+00:00 [info] <0.528.0> SCTP server listening on {127,0,1,1}:36412 (sctp_server:init/1:127) 2025-09-25T09:03:14.441944+00:00 [debug] <0.517.0> subscribe_(exometer_report_statsd, [ctr,s1ap,enb,all,rx], value, 1000, true, [{report_type,counter}], enabled) (exometer_report:subscribe_/7:1492) 2025-09-25T09:03:14.441996+00:00 [debug] <0.517.0> subscribe_(exometer_report_statsd, [ctr,s1ap,enb,all,rx_unknown_enb], value, 1000, true, [{report_type,counter}], enabled) (exometer_report:subscribe_/7:1492) 2025-09-25T09:03:14.441997+00:00 [info] <0.525.0> Supervisor: {local,osmo_s1gw_sup}. Started: id=sctp_server,pid=<0.528.0>. (supervisor:report_progress/3:2135) 2025-09-25T09:03:14.442029+00:00 [debug] <0.517.0> subscribe_(exometer_report_statsd, [ctr,s1ap,proxy,exception], value, 1000, true, [{report_type,counter}], enabled) (exometer_report:subscribe_/7:1492) 2025-09-25T09:03:14.442058+00:00 [debug] <0.517.0> subscribe_(exometer_report_statsd, [ctr,s1ap,proxy,in_pkt,all], value, 1000, true, [{report_type,counter}], enabled) (exometer_report:subscribe_/7:1492) 2025-09-25T09:03:14.442087+00:00 [debug] <0.517.0> subscribe_(exometer_report_statsd, [ctr,s1ap,proxy,in_pkt,decode_error], value, 1000, true, [{report_type,counter}], enabled) (exometer_report:subscribe_/7:1492) 2025-09-25T09:03:14.442084+00:00 [info] <0.529.0> PFCP peer @ {127,0,3,1} will talk to UPF @ {127,0,3,10} (pfcp_peer:init/1:177) 2025-09-25T09:03:14.442115+00:00 [debug] <0.517.0> subscribe_(exometer_report_statsd, [ctr,s1ap,proxy,in_pkt,drop,all], value, 1000, true, [{report_type,counter}], enabled) (exometer_report:subscribe_/7:1492) 2025-09-25T09:03:14.442138+00:00 [info] <0.529.0> State change: connecting -> connecting (pfcp_peer:connecting/3:194) 2025-09-25T09:03:14.442142+00:00 [info] <0.525.0> Supervisor: {local,osmo_s1gw_sup}. Started: id=pfcp_peer,pid=<0.529.0>. (supervisor:report_progress/3:2135) 2025-09-25T09:03:14.442143+00:00 [debug] <0.517.0> subscribe_(exometer_report_statsd, [ctr,s1ap,proxy,in_pkt,erab_setup_req], value, 1000, true, [{report_type,counter}], enabled) (exometer_report:subscribe_/7:1492) 2025-09-25T09:03:14.442183+00:00 [debug] <0.529.0> ctr_inc([ctr,pfcp,assoc_setup_req,tx], 1) (s1gw_metrics:ctr_inc/2:160) 2025-09-25T09:03:14.442197+00:00 [debug] <0.517.0> subscribe_(exometer_report_statsd, [ctr,s1ap,proxy,in_pkt,proc_error], value, 1000, true, [{report_type,counter}], enabled) (exometer_report:subscribe_/7:1492) 2025-09-25T09:03:14.442201+00:00 [info] <0.525.0> Supervisor: {local,osmo_s1gw_sup}. Started: id=gtpu_kpi,pid=<0.530.0>. (supervisor:report_progress/3:2135) 2025-09-25T09:03:14.442222+00:00 [debug] <0.529.0> Tx PFCP PDU: {pfcp,v1,association_setup_request,undefined,0,#{node_id => {node_id,<<127,0,3,1>>},recovery_time_stamp => {recovery_time_stamp,3967779794}}} (pfcp_peer:send_pdu/3:461) 2025-09-25T09:03:14.442230+00:00 [debug] <0.517.0> subscribe_(exometer_report_statsd, [ctr,s1ap,proxy,uplink_packets_queued], value, 1000, true, [{report_type,counter}], enabled) (exometer_report:subscribe_/7:1492) 2025-09-25T09:03:14.442272+00:00 [debug] <0.529.0> Tx encoded PFCP PDU to {127,0,3,10}:8805: <<32,5,0,21,0,0,0,0,0,60,0,5,0,127,0,3,1,0,96,0,4,236,127,131,210>> (pfcp_peer:send_data/2:441) 2025-09-25T09:03:14.442294+00:00 [debug] <0.517.0> subscribe_(exometer_report_statsd, [gauge,pfcp,associated], value, 1000, true, [{report_type,gauge}], enabled) (exometer_report:subscribe_/7:1492) 2025-09-25T09:03:14.442342+00:00 [debug] <0.517.0> subscribe_(exometer_report_statsd, [gauge,s1ap,enb,num_sctp_connections], value, 1000, true, [{report_type,gauge}], enabled) (exometer_report:subscribe_/7:1492) 2025-09-25T09:03:14.442397+00:00 [debug] <0.517.0> subscribe_(exometer_report_statsd, [gauge,s1ap,proxy,uplink_packets_queued], value, 1000, true, [{report_type,gauge}], enabled) (exometer_report:subscribe_/7:1492) 2025-09-25T09:03:14.442398+00:00 [error] <0.531.0> crasher: initial call: supervisor:erf/1, pid: <0.531.0>, registered_name: [], exit: {{bad_return,{erf,init,{stop,{invalid_oas_3_0_spec,{'$.type',<<"Value is not an object">>}}}}},[{gen_server,init_it,6,[{file,"gen_server.erl"},{line,2210}]},{proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,329}]}]}, ancestors: [osmo_s1gw_sup,<0.524.0>], message_queue_len: 0, messages: [], links: [<0.525.0>], dictionary: [], trap_exit: true, status: running, heap_size: 610, stack_size: 29, reductions: 771; neighbours: (proc_lib:crash_report/4:950) 2025-09-25T09:03:14.442495+00:00 [debug] <0.517.0> subscribe_(exometer_report_statsd, [ctr,s1ap,proxy,in_pkt,erab_mod_cnf], value, 1000, true, [{report_type,counter}], enabled) (exometer_report:subscribe_/7:1492) 2025-09-25T09:03:14.442537+00:00 [debug] <0.517.0> subscribe_(exometer_report_statsd, [ctr,s1ap,proxy,in_pkt,erab_mod_ind], value, 1000, true, [{report_type,counter}], enabled) (exometer_report:subscribe_/7:1492) 2025-09-25T09:03:14.442540+00:00 [error] <0.525.0> Supervisor: {local,osmo_s1gw_sup}. Context: start_error. Reason: {bad_return,{erf,init,{stop,{invalid_oas_3_0_spec,{'$.type',<<"Value is not an object">>}}}}}. Offender: id=rest_server,pid=undefined. (supervisor:start_children/2:937) 2025-09-25T09:03:14.442582+00:00 [debug] <0.517.0> subscribe_(exometer_report_statsd, [ctr,s1ap,proxy,in_pkt,erab_modify_req], value, 1000, true, [{report_type,counter}], enabled) (exometer_report:subscribe_/7:1492) 2025-09-25T09:03:14.442635+00:00 [debug] <0.517.0> subscribe_(exometer_report_statsd, [ctr,s1ap,proxy,in_pkt,erab_modify_rsp], value, 1000, true, [{report_type,counter}], enabled) (exometer_report:subscribe_/7:1492) 2025-09-25T09:03:14.442643+00:00 [notice] <0.528.0> Terminating, reason shutdown (sctp_server:terminate/2:184) 2025-09-25T09:03:14.442668+00:00 [debug] <0.517.0> subscribe_(exometer_report_statsd, [ctr,s1ap,proxy,in_pkt,erab_release_cmd], value, 1000, true, [{report_type,counter}], enabled) (exometer_report:subscribe_/7:1492) 2025-09-25T09:03:14.442701+00:00 [debug] <0.517.0> subscribe_(exometer_report_statsd, [ctr,s1ap,proxy,in_pkt,erab_release_ind], value, 1000, true, [{report_type,counter}], enabled) (exometer_report:subscribe_/7:1492) 2025-09-25T09:03:14.442734+00:00 [debug] <0.517.0> subscribe_(exometer_report_statsd, [ctr,s1ap,proxy,in_pkt,erab_release_rsp], value, 1000, true, [{report_type,counter}], enabled) (exometer_report:subscribe_/7:1492) 2025-09-25T09:03:14.442729+00:00 [notice] <0.465.0> Application: osmo_s1gw. Exited: {{shutdown,{failed_to_start_child,rest_server,{bad_return,{erf,init,{stop,{invalid_oas_3_0_spec,{'$.type',<<"Value is not an object">>}}}}}}},{osmo_s1gw_app,start,[normal,[]]}}. Type: permanent. (application_controller:info_exited/3:2125) 2025-09-25T09:03:14.442777+00:00 [debug] <0.517.0> subscribe_(exometer_report_statsd, [ctr,s1ap,proxy,in_pkt,erab_setup_rsp], value, 1000, true, [{report_type,counter}], enabled) (exometer_report:subscribe_/7:1492) 2025-09-25T09:03:14.442826+00:00 [debug] <0.517.0> subscribe_(exometer_report_statsd, [ctr,s1ap,proxy,in_pkt,handover_cmd], value, 1000, true, [{report_type,counter}], enabled) (exometer_report:subscribe_/7:1492) 2025-09-25T09:03:14.442856+00:00 [debug] <0.517.0> subscribe_(exometer_report_statsd, [ctr,s1ap,proxy,in_pkt,handover_req], value, 1000, true, [{report_type,counter}], enabled) (exometer_report:subscribe_/7:1492) 2025-09-25T09:03:14.442741+00:00 [error] <0.523.0> crasher: initial call: application_master:init/3, pid: <0.523.0>, registered_name: [], exit: {{{shutdown,{failed_to_start_child,rest_server,{bad_return,{erf,init,{stop,{invalid_oas_3_0_spec,{'$.type',<<"Value is not an object">>}}}}}}},{osmo_s1gw_app,start,[normal,[]]}},[{application_master,init,3,[{file,"application_master.erl"},{line,143}]},{proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,329}]}]}, ancestors: [application_controller,<0.10.0>], message_queue_len: 1, messages: [{'EXIT',<0.524.0>,normal}], links: [<0.465.0>], dictionary: [], trap_exit: true, status: running, heap_size: 376, stack_size: 29, reductions: 68; neighbours: (proc_lib:crash_report/4:950) 2025-09-25T09:03:14.442883+00:00 [debug] <0.517.0> subscribe_(exometer_report_statsd, [ctr,s1ap,proxy,in_pkt,handover_req_ack], value, 1000, true, [{report_type,counter}], enabled) (exometer_report:subscribe_/7:1492) 2025-09-25T09:03:14.442932+00:00 [debug] <0.517.0> subscribe_(exometer_report_statsd, [ctr,s1ap,proxy,in_pkt,init_ctx_req], value, 1000, true, [{report_type,counter}], enabled) (exometer_report:subscribe_/7:1492) 2025-09-25T09:03:14.442970+00:00 [debug] <0.517.0> subscribe_(exometer_report_statsd, [ctr,s1ap,proxy,in_pkt,init_ctx_rsp], value, 1000, true, [{report_type,counter}], enabled) (exometer_report:subscribe_/7:1492) 2025-09-25T09:03:14.442999+00:00 [debug] <0.517.0> subscribe_(exometer_report_statsd, [ctr,s1ap,proxy,in_pkt,release_ctx_cmd], value, 1000, true, [{report_type,counter}], enabled) (exometer_report:subscribe_/7:1492) 2025-09-25T09:03:14.443032+00:00 [debug] <0.517.0> subscribe_(exometer_report_statsd, [ctr,s1ap,proxy,in_pkt,release_ctx_compl], value, 1000, true, [{report_type,counter}], enabled) (exometer_report:subscribe_/7:1492) 2025-09-25T09:03:14.443061+00:00 [debug] <0.517.0> subscribe_(exometer_report_statsd, [ctr,s1ap,proxy,in_pkt,release_ctx_req], value, 1000, true, [{report_type,counter}], enabled) (exometer_report:subscribe_/7:1492) 2025-09-25T09:03:14.443099+00:00 [debug] <0.517.0> subscribe_(exometer_report_statsd, [ctr,s1ap,proxy,out_pkt,forward,all], value, 1000, true, [{report_type,counter}], enabled) (exometer_report:subscribe_/7:1492) 2025-09-25T09:03:14.443132+00:00 [debug] <0.517.0> subscribe_(exometer_report_statsd, [ctr,s1ap,proxy,out_pkt,forward,proc], value, 1000, true, [{report_type,counter}], enabled) (exometer_report:subscribe_/7:1492) 2025-09-25T09:03:14.443160+00:00 [debug] <0.517.0> subscribe_(exometer_report_statsd, [ctr,s1ap,proxy,out_pkt,forward,unmodified], value, 1000, true, [{report_type,counter}], enabled) (exometer_report:subscribe_/7:1492) 2025-09-25T09:03:14.443196+00:00 [debug] <0.517.0> subscribe_(exometer_report_statsd, [ctr,s1ap,proxy,out_pkt,reply,all], value, 1000, true, [{report_type,counter}], enabled) (exometer_report:subscribe_/7:1492) 2025-09-25T09:03:14.443224+00:00 [debug] <0.517.0> subscribe_(exometer_report_statsd, [ctr,s1ap,proxy,out_pkt,reply,erab_setup_rsp], value, 1000, true, [{report_type,counter}], enabled) (exometer_report:subscribe_/7:1492) MTC@9897b8b3263e: External command `https://jenkins.osmocom.org/jenkins/job/ttcn3-s1gw-test/ws/ttcn3-tcpdump-start.sh S1GW_Tests.TC_setup' was executed successfully (exit status: 0). MTC@9897b8b3263e: Initializing variables, timers and ports of component type S1GW_Tests.test_CT inside testcase TC_setup. MTC@9897b8b3263e: Component type S1GW_Tests.test_CT was initialized. MTC@9897b8b3263e: Creating new alive PTC with component type Mutex.MutexDispCT, component name: MutexDispCT-TC_setup. HC@9897b8b3263e: PTC was created. Component reference: 3, component type: Mutex.MutexDispCT, component name: MutexDispCT-TC_setup, testcase name: TC_setup, process id: 5107. MutexDispCT-TC_setup(3)@9897b8b3263e: Initializing variables, timers and ports of component type Mutex.MutexDispCT inside testcase TC_setup. MTC@9897b8b3263e: PTC was created. Component reference: 3, alive: yes, type: Mutex.MutexDispCT, component name: MutexDispCT-TC_setup. MTC@9897b8b3263e: Starting function f_MutexDisp_main() on component MutexDispCT-TC_setup(3). MTC@9897b8b3263e: Function was started. MTC@9897b8b3263e: Creating new PTC with component type StatsD_Checker.StatsD_Checker_CT, component name: StatsDSRV-STATS. MutexDispCT-TC_setup(3)@9897b8b3263e: Component type Mutex.MutexDispCT was initialized. MutexDispCT-TC_setup(3)@9897b8b3263e: Starting function f_MutexDisp_main(). HC@9897b8b3263e: PTC was created. Component reference: 4, component type: StatsD_Checker.StatsD_Checker_CT, component name: StatsDSRV-STATS, testcase name: TC_setup, process id: 5108. StatsDSRV-STATS(4)@9897b8b3263e: Initializing variables, timers and ports of component type StatsD_Checker.StatsD_Checker_CT inside testcase TC_setup. MTC@9897b8b3263e: PTC was created. Component reference: 4, alive: no, type: StatsD_Checker.StatsD_Checker_CT, component name: StatsDSRV-STATS. MTC@9897b8b3263e: Starting function main("127.0.4.10", 8125, 5.000000) on component StatsDSRV-STATS(4). MTC@9897b8b3263e: Function was started. MTC@9897b8b3263e: Creating new alive PTC with component type S1AP_Server.S1AP_Server_CT, component name: S1APSRV-TC_setup. StatsDSRV-STATS(4)@9897b8b3263e: Component type StatsD_Checker.StatsD_Checker_CT was initialized. StatsDSRV-STATS(4)@9897b8b3263e: Starting function main("127.0.4.10", 8125, 5.000000). StatsDSRV-STATS(4)@9897b8b3263e: Mapping port StatsDSRV-STATS(4):STATS to system:STATS. StatsDSRV-STATS(4)@9897b8b3263e: Map operation of StatsDSRV-STATS(4):STATS to system:STATS finished. HC@9897b8b3263e: PTC was created. Component reference: 5, component type: S1AP_Server.S1AP_Server_CT, component name: S1APSRV-TC_setup, testcase name: TC_setup, process id: 5109. S1APSRV-TC_setup(5)@9897b8b3263e: Initializing variables, timers and ports of component type S1AP_Server.S1AP_Server_CT inside testcase TC_setup. MTC@9897b8b3263e: PTC was created. Component reference: 5, alive: yes, type: S1AP_Server.S1AP_Server_CT, component name: S1APSRV-TC_setup. MTC@9897b8b3263e: Starting function main({ local_ip := "127.0.2.10", local_port := 36412 }) on component S1APSRV-TC_setup(5). MTC@9897b8b3263e: Function was started. MTC@9897b8b3263e: Creating new alive PTC with component type PFCP_Emulation.PFCP_Emulation_CT, component name: PFCPEM-TC_setup. S1APSRV-TC_setup(5)@9897b8b3263e: Component type S1AP_Server.S1AP_Server_CT was initialized. S1APSRV-TC_setup(5)@9897b8b3263e: Starting function main({ local_ip := "127.0.2.10", local_port := 36412 }). S1APSRV-TC_setup(5)@9897b8b3263e: Mapping port S1APSRV-TC_setup(5):S1AP to system:S1AP_CODEC_PT. S1APSRV-TC_setup(5)@9897b8b3263e: Map operation of S1APSRV-TC_setup(5):S1AP to system:S1AP_CODEC_PT finished. S1APSRV-TC_setup(5)@9897b8b3263e: Warning: sizes of 'struct sctp_event_subscribe': compile-time 14, kernel: 14 S1APSRV-TC_setup(5)@9897b8b3263e: SCTP server listening on "127.0.2.10":36412 HC@9897b8b3263e: PTC was created. Component reference: 6, component type: PFCP_Emulation.PFCP_Emulation_CT, component name: PFCPEM-TC_setup, testcase name: TC_setup, process id: 5110. PFCPEM-TC_setup(6)@9897b8b3263e: Initializing variables, timers and ports of component type PFCP_Emulation.PFCP_Emulation_CT inside testcase TC_setup. MTC@9897b8b3263e: PTC was created. Component reference: 6, alive: yes, type: PFCP_Emulation.PFCP_Emulation_CT, component name: PFCPEM-TC_setup. MTC@9897b8b3263e: Starting function main({ pfcp_bind_ip := "127.0.3.10", pfcp_bind_port := 8805, pfcp_remote_ip := "127.0.3.1", pfcp_remote_port := 8805, role := UPF (1) }) on component PFCPEM-TC_setup(6). MTC@9897b8b3263e: Function was started. PFCPEM-TC_setup(6)@9897b8b3263e: Component type PFCP_Emulation.PFCP_Emulation_CT was initialized. PFCPEM-TC_setup(6)@9897b8b3263e: Starting function main({ pfcp_bind_ip := "127.0.3.10", pfcp_bind_port := 8805, pfcp_remote_ip := "127.0.3.1", pfcp_remote_port := 8805, role := UPF (1) }). PFCPEM-TC_setup(6)@9897b8b3263e: Mapping port PFCPEM-TC_setup(6):PFCP to system:PFCP. PFCPEM-TC_setup(6)@9897b8b3263e: Map operation of PFCPEM-TC_setup(6):PFCP to system:PFCP finished. MTC@9897b8b3263e: Creating new alive PTC with component type S1GW_ConnHdlr.ConnHdlr, component name: ConnHdlr-TC_setup-0. HC@9897b8b3263e: PTC was created. Component reference: 7, component type: S1GW_ConnHdlr.ConnHdlr, component name: ConnHdlr-TC_setup-0, testcase name: TC_setup, process id: 5111. ConnHdlr-TC_setup-0(7)@9897b8b3263e: Initializing variables, timers and ports of component type S1GW_ConnHdlr.ConnHdlr inside testcase TC_setup. MTC@9897b8b3263e: PTC was created. Component reference: 7, alive: yes, type: S1GW_ConnHdlr.ConnHdlr, component name: ConnHdlr-TC_setup-0. MTC@9897b8b3263e: Connecting ports ConnHdlr-TC_setup-0(7):STATSD_PROC and StatsDSRV-STATS(4):STATSD_PROC. ConnHdlr-TC_setup-0(7)@9897b8b3263e: Component type S1GW_ConnHdlr.ConnHdlr was initialized. MTC@9897b8b3263e: Connect operation on ConnHdlr-TC_setup-0(7):STATSD_PROC and StatsDSRV-STATS(4):STATSD_PROC finished. MTC@9897b8b3263e: Connecting ports ConnHdlr-TC_setup-0(7):S1AP_CONN and S1APSRV-TC_setup(5):S1AP_CLIENT. MTC@9897b8b3263e: Connect operation on ConnHdlr-TC_setup-0(7):S1AP_CONN and S1APSRV-TC_setup(5):S1AP_CLIENT finished. MTC@9897b8b3263e: Connecting ports ConnHdlr-TC_setup-0(7):S1AP_PROC and S1APSRV-TC_setup(5):S1AP_PROC. MTC@9897b8b3263e: Connect operation on ConnHdlr-TC_setup-0(7):S1AP_PROC and S1APSRV-TC_setup(5):S1AP_PROC finished. MTC@9897b8b3263e: Connecting ports ConnHdlr-TC_setup-0(7):PFCP and PFCPEM-TC_setup(6):CLIENT. MTC@9897b8b3263e: Connect operation on ConnHdlr-TC_setup-0(7):PFCP and PFCPEM-TC_setup(6):CLIENT finished. MTC@9897b8b3263e: Connecting ports ConnHdlr-TC_setup-0(7):PFCP_PROC and PFCPEM-TC_setup(6):CLIENT_PROC. MTC@9897b8b3263e: Connect operation on ConnHdlr-TC_setup-0(7):PFCP_PROC and PFCPEM-TC_setup(6):CLIENT_PROC finished. MTC@9897b8b3263e: Connecting ports MutexDispCT-TC_setup(3):LOCK and ConnHdlr-TC_setup-0(7):LOCK. MTC@9897b8b3263e: Connect operation on MutexDispCT-TC_setup(3):LOCK and ConnHdlr-TC_setup-0(7):LOCK finished. MTC@9897b8b3263e: Connecting ports MutexDispCT-TC_setup(3):UNLOCK and ConnHdlr-TC_setup-0(7):UNLOCK. MTC@9897b8b3263e: Connect operation on MutexDispCT-TC_setup(3):UNLOCK and ConnHdlr-TC_setup-0(7):UNLOCK finished. MTC@9897b8b3263e: Starting function f_ConnHdlr_init(refers(S1GW_ConnHdlr.f_ConnHdlr_pfcp_assoc_handler), "ConnHdlr-TC_setup-0", { idx := 0, genb_id := { pLMNidentity := '00F110'O, eNB_ID := { macroENB_ID := '00000000000000000000'B }, iE_Extensions := omit }, statsd_prefix := "s1gw.", pfcp_loc_addr := "127.0.3.10", pfcp_rem_addr := "127.0.3.1", mme_ue_id := 4242, erabs := { { erab_id := 0, u2c := { teid := '00010000'O, tla := "127.0.0.1" }, c2u := { teid := '01010000'O, tla := "127.0.1.1" }, a2u := { teid := '02020000'O, tla := "127.0.2.2" }, u2a := { teid := '00020000'O, tla := "127.0.0.2" }, u2cm := { teid := '00110000'O, tla := "127.127.0.1" }, u2am := { teid := '00220000'O, tla := "127.127.0.2" }, pfcp_loc_seid := '5454434E2D330000'O, pfcp_rem_seid := omit } } }) on component ConnHdlr-TC_setup-0(7). MTC@9897b8b3263e: Function was started. ConnHdlr-TC_setup-0(7)@9897b8b3263e: Starting function f_ConnHdlr_init(refers(S1GW_ConnHdlr.f_ConnHdlr_pfcp_assoc_handler), "ConnHdlr-TC_setup-0", { idx := 0, genb_id := { pLMNidentity := '00F110'O, eNB_ID := { macroENB_ID := '00000000000000000000'B }, iE_Extensions := omit }, statsd_prefix := "s1gw.", pfcp_loc_addr := "127.0.3.10", pfcp_rem_addr := "127.0.3.1", mme_ue_id := 4242, erabs := { { erab_id := 0, u2c := { teid := '00010000'O, tla := "127.0.0.1" }, c2u := { teid := '01010000'O, tla := "127.0.1.1" }, a2u := { teid := '02020000'O, tla := "127.0.2.2" }, u2a := { teid := '00020000'O, tla := "127.0.0.2" }, u2cm := { teid := '00110000'O, tla := "127.127.0.1" }, u2am := { teid := '00220000'O, tla := "127.127.0.2" }, pfcp_loc_seid := '5454434E2D330000'O, pfcp_rem_seid := omit } } }). Kernel pid terminated (application_controller) ("{application_start_failure,osmo_s1gw,{{shutdown,{failed_to_start_child,rest_server,{bad_return,{erf,init,{stop,{invalid_oas_3_0_spec,{'$.type',<<"Value is not an object">>}}}}}}},{osmo_s1gw_app,start,[normal,[]]}}}")

Crash dump is being written to: erl_crash.dump...done [testenv] Looking for a coredump on lxc host [testenv] + ['ip', '-j', '-o', '-4', 'addr', 'show', 'dev', 'eth0'] [testenv] No coredump found [testenv] s1gw unexpected exit during S1GW_Tests.TC_setup! rc=0 [testenv] Waiting until test has stopped... StatsDSRV-STATS(4)@9897b8b3263e: Timeout waiting for "s1gw.gauge.pfcp.associated.value" StatsDSRV-STATS(4)@9897b8b3263e: setverdict(fail): none -> fail reason: ""StatsD_Checker.ttcnpp:212 : Timeout waiting for metrics: { { name := "s1gw.gauge.pfcp.associated.value", mtype := "g" } }{ false }"", new component reason: ""StatsD_Checker.ttcnpp:212 : Timeout waiting for metrics: { { name := "s1gw.gauge.pfcp.associated.value", mtype := "g" } }{ false }"" StatsDSRV-STATS(4)@9897b8b3263e: Stopping testcase execution from "StatsD_Checker.ttcnpp":212 StatsDSRV-STATS(4)@9897b8b3263e: Stopping MTC. The current test case will be terminated. MC@9897b8b3263e: Test Component 4 has requested to stop MTC. Terminating current testcase execution. StatsDSRV-STATS(4)@9897b8b3263e: Stopping test component execution. MutexDispCT-TC_setup(3)@9897b8b3263e: Kill was requested from MC. PFCPEM-TC_setup(6)@9897b8b3263e: Kill was requested from MC. PFCPEM-TC_setup(6)@9897b8b3263e: Terminating test component execution. MutexDispCT-TC_setup(3)@9897b8b3263e: Terminating test component execution. ConnHdlr-TC_setup-0(7)@9897b8b3263e: Kill was requested from MC. ConnHdlr-TC_setup-0(7)@9897b8b3263e: Terminating test component execution. S1APSRV-TC_setup(5)@9897b8b3263e: Kill was requested from MC. MTC@9897b8b3263e: Stopping test component execution. S1APSRV-TC_setup(5)@9897b8b3263e: Terminating test component execution. StatsDSRV-STATS(4)@9897b8b3263e: Function main was stopped. PTC terminates. PFCPEM-TC_setup(6)@9897b8b3263e: Function main was stopped. PTC terminates. ConnHdlr-TC_setup-0(7)@9897b8b3263e: Function f_ConnHdlr_init was stopped. PTC terminates. StatsDSRV-STATS(4)@9897b8b3263e: Terminating component type StatsD_Checker.StatsD_Checker_CT. S1APSRV-TC_setup(5)@9897b8b3263e: Function main was stopped. PTC terminates. ConnHdlr-TC_setup-0(7)@9897b8b3263e: Terminating component type S1GW_ConnHdlr.ConnHdlr. MutexDispCT-TC_setup(3)@9897b8b3263e: Function f_MutexDisp_main was stopped. PTC terminates. PFCPEM-TC_setup(6)@9897b8b3263e: Terminating component type PFCP_Emulation.PFCP_Emulation_CT. S1APSRV-TC_setup(5)@9897b8b3263e: Terminating component type S1AP_Server.S1AP_Server_CT. MTC@9897b8b3263e: Terminating component type S1GW_Tests.test_CT. MutexDispCT-TC_setup(3)@9897b8b3263e: Terminating component type Mutex.MutexDispCT. MTC@9897b8b3263e: Component type S1GW_Tests.test_CT was shut down inside testcase TC_setup. MutexDispCT-TC_setup(3)@9897b8b3263e: Component type Mutex.MutexDispCT was shut down inside testcase TC_setup. MutexDispCT-TC_setup(3)@9897b8b3263e: Final verdict of PTC: none StatsDSRV-STATS(4)@9897b8b3263e: Component type StatsD_Checker.StatsD_Checker_CT was shut down inside testcase TC_setup. StatsDSRV-STATS(4)@9897b8b3263e: Final verdict of PTC: fail reason: ""StatsD_Checker.ttcnpp:212 : Timeout waiting for metrics: { { name := "s1gw.gauge.pfcp.associated.value", mtype := "g" } }{ false }"" PFCPEM-TC_setup(6)@9897b8b3263e: Component type PFCP_Emulation.PFCP_Emulation_CT was shut down inside testcase TC_setup. S1APSRV-TC_setup(5)@9897b8b3263e: Component type S1AP_Server.S1AP_Server_CT was shut down inside testcase TC_setup. S1APSRV-TC_setup(5)@9897b8b3263e: Final verdict of PTC: none PFCPEM-TC_setup(6)@9897b8b3263e: Final verdict of PTC: none ConnHdlr-TC_setup-0(7)@9897b8b3263e: Component type S1GW_ConnHdlr.ConnHdlr was shut down inside testcase TC_setup. ConnHdlr-TC_setup-0(7)@9897b8b3263e: Final verdict of PTC: none MTC@9897b8b3263e: Setting final verdict of the test case. MTC@9897b8b3263e: Local verdict of MTC: none MTC@9897b8b3263e: Local verdict of PTC MutexDispCT-TC_setup(3): none (none -> none) MTC@9897b8b3263e: Local verdict of PTC StatsDSRV-STATS(4): fail (none -> fail) reason: ""StatsD_Checker.ttcnpp:212 : Timeout waiting for metrics: { { name := "s1gw.gauge.pfcp.associated.value", mtype := "g" } }{ false }"" MTC@9897b8b3263e: Local verdict of PTC S1APSRV-TC_setup(5): none (fail -> fail) MTC@9897b8b3263e: Local verdict of PTC PFCPEM-TC_setup(6): none (fail -> fail) MTC@9897b8b3263e: Local verdict of PTC ConnHdlr-TC_setup-0(7): none (fail -> fail) MTC@9897b8b3263e: Starting external command `https://jenkins.osmocom.org/jenkins/job/ttcn3-s1gw-test/ws/ttcn3-tcpdump-stop.sh S1GW_Tests.TC_setup fail'. Thu Sep 25 09:03:20 UTC 2025 ------ S1GW_Tests.TC_setup fail ------

Waiting for packet dumper to finish... 0 (prev_count=-1, count=3096) MTC@9897b8b3263e: External command `https://jenkins.osmocom.org/jenkins/job/ttcn3-s1gw-test/ws/ttcn3-tcpdump-stop.sh S1GW_Tests.TC_setup fail' was executed successfully (exit status: 0). MTC@9897b8b3263e: Starting external command `https://jenkins.osmocom.org/jenkins/job/ttcn3-s1gw-test/ws/ttcn3-tcpdump-start.sh S1GW_Tests.TC_setup_multi'. ------ S1GW_Tests.TC_setup_multi ------ Thu Sep 25 09:03:21 UTC 2025 /usr/bin/dumpcap -q -s 1520 -n -i any -w "https://jenkins.osmocom.org/jenkins/job/ttcn3-s1gw-test/474/artifact/logs/testsuite/S1GW_Tests.TC_setup_multi.pcap" >https://jenkins.osmocom.org/jenkins/job/ttcn3-s1gw-test/474/artifact/logs/testsuite/S1GW_Tests.TC_setup_multi.pcap.stdout 2>/tmp/cmderr & Waiting for packet dumper to start... 0 [testenv] Stopping podman container [testenv] + ['podman', 'kill', 'testenv-s1gw-osmocom-nightly-20250925-0903-58f9891f-0'] testenv-s1gw-osmocom-nightly-20250925-0903-58f9891f-0 [testenv] Stopping testsuite (1690931) [testenv] feed_watchdog_loop: podman container has stopped [testenv] Logs saved to: https://jenkins.osmocom.org/jenkins/job/ttcn3-s1gw-test/474/artifact/logs/  + RC=1 + [ 1 = 0 ] + uptime + grep --color=always -o load.* load average: 3.33, 1.67, 1.33 + exit 1 Build step 'Execute shell' marked build as failure Recording test results [Checks API] No suitable checks publisher found.