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 [1;37m[info] <0.469.0> Supervisor: {local,kernel_sup}. Started: id=rex,pid=<0.480.0>. (supervisor:report_progress/3:2135)[0m 2025-09-25T09:03:14.437102+00:00 [1;37m[info] <0.469.0> Supervisor: {local,kernel_sup}. Started: id=global_name_server,pid=<0.482.0>. (supervisor:report_progress/3:2135)[0m 2025-09-25T09:03:14.437132+00:00 [1;37m[info] <0.485.0> Supervisor: {local,net_sup}. Started: id=erl_epmd,pid=<0.486.0>. (supervisor:report_progress/3:2135)[0m 2025-09-25T09:03:14.437140+00:00 [1;37m[info] <0.485.0> Supervisor: {local,net_sup}. Started: id=auth,pid=<0.487.0>. (supervisor:report_progress/3:2135)[0m 2025-09-25T09:03:14.437381+00:00 [1;37m[info] <0.485.0> Supervisor: {local,net_sup}. Started: id=net_kernel,pid=<0.488.0>. (supervisor:report_progress/3:2135)[0m 2025-09-25T09:03:14.437394+00:00 [1;37m[info] <0.469.0> Supervisor: {local,kernel_sup}. Started: id=net_sup,pid=<0.485.0>. (supervisor:report_progress/3:2135)[0m 2025-09-25T09:03:14.437408+00:00 [1;37m[info] <0.469.0> Supervisor: {local,kernel_sup}. Started: id=global_group,pid=<0.491.0>. (supervisor:report_progress/3:2135)[0m 2025-09-25T09:03:14.437418+00:00 [1;37m[info] <0.469.0> Supervisor: {local,kernel_sup}. Started: id=erl_signal_server,pid=<0.493.0>. (supervisor:report_progress/3:2135)[0m 2025-09-25T09:03:14.437473+00:00 [1;37m[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)[0m 2025-09-25T09:03:14.437487+00:00 [1;37m[info] <0.469.0> Supervisor: {local,kernel_sup}. Started: id=user,pid=<0.494.0>. (supervisor:report_progress/3:2135)[0m 2025-09-25T09:03:14.437502+00:00 [1;37m[info] <0.498.0> Supervisor: {local,logger_sup}. Started: id=logger_handler_watcher,pid=<0.499.0>. (supervisor:report_progress/3:2135)[0m 2025-09-25T09:03:14.437531+00:00 [1;37m[info] <0.498.0> Supervisor: {local,logger_sup}. Started: id=logger_proxy,pid=<0.500.0>. (supervisor:report_progress/3:2135)[0m 2025-09-25T09:03:14.437537+00:00 [1;37m[info] <0.469.0> Supervisor: {local,kernel_sup}. Started: id=logger_sup,pid=<0.498.0>. (supervisor:report_progress/3:2135)[0m 2025-09-25T09:03:14.437552+00:00 [1;37m[info] <0.469.0> Supervisor: {local,kernel_sup}. Started: id=kernel_config,pid=<0.501.0>. (supervisor:report_progress/3:2135)[0m 2025-09-25T09:03:14.437767+00:00 [1;37m[info] <0.464.0> Simple handler buffer full, dropped 3 messages[0m 2025-09-25T09:03:14.438948+00:00 [1;37m[info] <0.465.0> Application: kernel. Started at: 'osmo-s1gw@9897b8b3263e'. (application_controller:info_started/2:2113)[0m 2025-09-25T09:03:14.438993+00:00 [1;37m[info] <0.465.0> Application: stdlib. Started at: 'osmo-s1gw@9897b8b3263e'. (application_controller:info_started/2:2113)[0m 2025-09-25T09:03:14.439038+00:00 [1;37m[info] <0.465.0> Application: logger_color_formatter. Started at: 'osmo-s1gw@9897b8b3263e'. (application_controller:info_started/2:2113)[0m 2025-09-25T09:03:14.439070+00:00 [1;37m[info] <0.465.0> Application: logger_gsmtap. Started at: 'osmo-s1gw@9897b8b3263e'. (application_controller:info_started/2:2113)[0m 2025-09-25T09:03:14.439108+00:00 [1;37m[info] <0.465.0> Application: pfcplib. Started at: 'osmo-s1gw@9897b8b3263e'. (application_controller:info_started/2:2113)[0m 2025-09-25T09:03:14.439136+00:00 [1;37m[info] <0.465.0> Application: xmerl. Started at: 'osmo-s1gw@9897b8b3263e'. (application_controller:info_started/2:2113)[0m 2025-09-25T09:03:14.439168+00:00 [1;37m[info] <0.465.0> Application: jiffy. Started at: 'osmo-s1gw@9897b8b3263e'. (application_controller:info_started/2:2113)[0m 2025-09-25T09:03:14.439199+00:00 [1;37m[info] <0.465.0> Application: enftables. Started at: 'osmo-s1gw@9897b8b3263e'. (application_controller:info_started/2:2113)[0m 2025-09-25T09:03:14.439256+00:00 [1;37m[info] <0.510.0> Supervisor: {local,setup_sup}. Started: id=setup_srv,pid=<0.511.0>. (supervisor:report_progress/3:2135)[0m 2025-09-25T09:03:14.439319+00:00 [1;36m[notice] <0.511.0> Setup running ...[0m 2025-09-25T09:03:14.439662+00:00 [1;36m[notice] <0.511.0> Directories verified. Res = ok[0m 2025-09-25T09:03:14.439730+00:00 [1;36m[notice] <0.511.0> Setup finished processing hooks (Mode=normal)...[0m 2025-09-25T09:03:14.439765+00:00 [1;37m[info] <0.465.0> Application: setup. Started at: 'osmo-s1gw@9897b8b3263e'. (application_controller:info_started/2:2113)[0m 2025-09-25T09:03:14.439801+00:00 [1;37m[info] <0.465.0> Application: syntax_tools. Started at: 'osmo-s1gw@9897b8b3263e'. (application_controller:info_started/2:2113)[0m 2025-09-25T09:03:14.439830+00:00 [1;37m[info] <0.465.0> Application: parse_trans. Started at: 'osmo-s1gw@9897b8b3263e'. (application_controller:info_started/2:2113)[0m 2025-09-25T09:03:14.440333+00:00 [1;37m[info] <0.514.0> Supervisor: {local,exometer_core_sup}. Started: id=exometer_admin,pid=<0.515.0>. (supervisor:report_progress/3:2135)[0m 2025-09-25T09:03:14.440421+00:00 [1;37m[info] <0.514.0> Supervisor: {local,exometer_core_sup}. Started: id=exometer_cache,pid=<0.516.0>. (supervisor:report_progress/3:2135)[0m 2025-09-25T09:03:14.440462+00:00 [1;37m[info] <0.514.0> Supervisor: {local,exometer_core_sup}. Started: id=exometer_report,pid=<0.517.0>. (supervisor:report_progress/3:2135)[0m 2025-09-25T09:03:14.440497+00:00 [1;37m[info] <0.514.0> Supervisor: {local,exometer_core_sup}. Started: id=exometer_report_logger_sup,pid=<0.518.0>. (supervisor:report_progress/3:2135)[0m 2025-09-25T09:03:14.440543+00:00 [1;37m[info] <0.514.0> Supervisor: {local,exometer_core_sup}. Started: id=exometer_alias,pid=<0.519.0>. (supervisor:report_progress/3:2135)[0m 2025-09-25T09:03:14.440673+00:00 [1;37m[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)[0m 2025-09-25T09:03:14.440802+00:00 [1;37m[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)[0m 2025-09-25T09:03:14.440847+00:00 [1;37m[info] <0.465.0> Application: exometer_core. Started at: 'osmo-s1gw@9897b8b3263e'. (application_controller:info_started/2:2113)[0m 2025-09-25T09:03:14.440903+00:00 [1;37m[info] <0.465.0> Application: exometer_report_statsd. Started at: 'osmo-s1gw@9897b8b3263e'. (application_controller:info_started/2:2113)[0m 2025-09-25T09:03:14.440876+00:00 [1;37m[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)[0m 2025-09-25T09:03:14.440948+00:00 [1;37m[info] <0.465.0> Application: compiler. Started at: 'osmo-s1gw@9897b8b3263e'. (application_controller:info_started/2:2113)[0m 2025-09-25T09:03:14.440972+00:00 [0;38m[debug] <0.503.0> Supervisor: {local,kernel_safe_sup}. Started: id=inet_gethost_native_sup,pid=<0.521.0>. (supervisor:report_progress/3:2145)[0m 2025-09-25T09:03:14.440988+00:00 [1;37m[info] <0.465.0> Application: elli. Started at: 'osmo-s1gw@9897b8b3263e'. (application_controller:info_started/2:2113)[0m 2025-09-25T09:03:14.441033+00:00 [1;37m[info] <0.465.0> Application: njson. Started at: 'osmo-s1gw@9897b8b3263e'. (application_controller:info_started/2:2113)[0m 2025-09-25T09:03:14.441073+00:00 [1;37m[info] <0.465.0> Application: ndto. Started at: 'osmo-s1gw@9897b8b3263e'. (application_controller:info_started/2:2113)[0m 2025-09-25T09:03:14.441109+00:00 [1;37m[info] <0.465.0> Application: erf. Started at: 'osmo-s1gw@9897b8b3263e'. (application_controller:info_started/2:2113)[0m 2025-09-25T09:03:14.441178+00:00 [1;37m[info] <0.525.0> Initiating metrics (s1gw_metrics:init/0:129)[0m 2025-09-25T09:03:14.441295+00:00 [0;38m[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)[0m 2025-09-25T09:03:14.441397+00:00 [0;38m[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)[0m 2025-09-25T09:03:14.441431+00:00 [0;38m[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)[0m 2025-09-25T09:03:14.441477+00:00 [0;38m[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)[0m 2025-09-25T09:03:14.441567+00:00 [0;38m[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)[0m 2025-09-25T09:03:14.441604+00:00 [0;38m[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)[0m 2025-09-25T09:03:14.441692+00:00 [0;38m[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)[0m 2025-09-25T09:03:14.441738+00:00 [0;38m[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)[0m 2025-09-25T09:03:14.441773+00:00 [0;38m[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)[0m 2025-09-25T09:03:14.441807+00:00 [1;37m[info] <0.525.0> Supervisor: {local,osmo_s1gw_sup}. Started: id=enb_registry,pid=<0.526.0>. (supervisor:report_progress/3:2135)[0m 2025-09-25T09:03:14.441824+00:00 [0;38m[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)[0m 2025-09-25T09:03:14.441865+00:00 [0;38m[debug] <0.517.0> subscribe_(exometer_report_statsd, [ctr,pfcp,unexpected_pdu], value, 1000, true, [{report_type,counter}], enabled) (exometer_report:subscribe_/7:1492)[0m 2025-09-25T09:03:14.441930+00:00 [1;37m[info] <0.528.0> SCTP server listening on {127,0,1,1}:36412 (sctp_server:init/1:127)[0m 2025-09-25T09:03:14.441944+00:00 [0;38m[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)[0m 2025-09-25T09:03:14.441996+00:00 [0;38m[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)[0m 2025-09-25T09:03:14.441997+00:00 [1;37m[info] <0.525.0> Supervisor: {local,osmo_s1gw_sup}. Started: id=sctp_server,pid=<0.528.0>. (supervisor:report_progress/3:2135)[0m 2025-09-25T09:03:14.442029+00:00 [0;38m[debug] <0.517.0> subscribe_(exometer_report_statsd, [ctr,s1ap,proxy,exception], value, 1000, true, [{report_type,counter}], enabled) (exometer_report:subscribe_/7:1492)[0m 2025-09-25T09:03:14.442058+00:00 [0;38m[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)[0m 2025-09-25T09:03:14.442087+00:00 [0;38m[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)[0m 2025-09-25T09:03:14.442084+00:00 [1;37m[info] <0.529.0> PFCP peer @ {127,0,3,1} will talk to UPF @ {127,0,3,10} (pfcp_peer:init/1:177)[0m 2025-09-25T09:03:14.442115+00:00 [0;38m[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)[0m 2025-09-25T09:03:14.442138+00:00 [1;37m[info] <0.529.0> State change: connecting -> connecting (pfcp_peer:connecting/3:194)[0m 2025-09-25T09:03:14.442142+00:00 [1;37m[info] <0.525.0> Supervisor: {local,osmo_s1gw_sup}. Started: id=pfcp_peer,pid=<0.529.0>. (supervisor:report_progress/3:2135)[0m 2025-09-25T09:03:14.442143+00:00 [0;38m[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)[0m 2025-09-25T09:03:14.442183+00:00 [0;38m[debug] <0.529.0> ctr_inc([ctr,pfcp,assoc_setup_req,tx], 1) (s1gw_metrics:ctr_inc/2:160)[0m 2025-09-25T09:03:14.442197+00:00 [0;38m[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)[0m 2025-09-25T09:03:14.442201+00:00 [1;37m[info] <0.525.0> Supervisor: {local,osmo_s1gw_sup}. Started: id=gtpu_kpi,pid=<0.530.0>. (supervisor:report_progress/3:2135)[0m 2025-09-25T09:03:14.442222+00:00 [0;38m[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)[0m 2025-09-25T09:03:14.442230+00:00 [0;38m[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)[0m 2025-09-25T09:03:14.442272+00:00 [0;38m[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)[0m 2025-09-25T09:03:14.442294+00:00 [0;38m[debug] <0.517.0> subscribe_(exometer_report_statsd, [gauge,pfcp,associated], value, 1000, true, [{report_type,gauge}], enabled) (exometer_report:subscribe_/7:1492)[0m 2025-09-25T09:03:14.442342+00:00 [0;38m[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)[0m 2025-09-25T09:03:14.442397+00:00 [0;38m[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)[0m 2025-09-25T09:03:14.442398+00:00 [1;31m[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)[0m 2025-09-25T09:03:14.442495+00:00 [0;38m[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)[0m 2025-09-25T09:03:14.442537+00:00 [0;38m[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)[0m 2025-09-25T09:03:14.442540+00:00 [1;31m[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)[0m 2025-09-25T09:03:14.442582+00:00 [0;38m[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)[0m 2025-09-25T09:03:14.442635+00:00 [0;38m[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)[0m 2025-09-25T09:03:14.442643+00:00 [1;36m[notice] <0.528.0> Terminating, reason shutdown (sctp_server:terminate/2:184)[0m 2025-09-25T09:03:14.442668+00:00 [0;38m[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)[0m 2025-09-25T09:03:14.442701+00:00 [0;38m[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)[0m 2025-09-25T09:03:14.442734+00:00 [0;38m[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)[0m 2025-09-25T09:03:14.442729+00:00 [1;36m[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)[0m 2025-09-25T09:03:14.442777+00:00 [0;38m[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)[0m 2025-09-25T09:03:14.442826+00:00 [0;38m[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)[0m 2025-09-25T09:03:14.442856+00:00 [0;38m[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)[0m 2025-09-25T09:03:14.442741+00:00 [1;31m[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)[0m 2025-09-25T09:03:14.442883+00:00 [0;38m[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)[0m 2025-09-25T09:03:14.442932+00:00 [0;38m[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)[0m 2025-09-25T09:03:14.442970+00:00 [0;38m[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)[0m 2025-09-25T09:03:14.442999+00:00 [0;38m[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)[0m 2025-09-25T09:03:14.443032+00:00 [0;38m[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)[0m 2025-09-25T09:03:14.443061+00:00 [0;38m[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)[0m 2025-09-25T09:03:14.443099+00:00 [0;38m[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)[0m 2025-09-25T09:03:14.443132+00:00 [0;38m[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)[0m 2025-09-25T09:03:14.443160+00:00 [0;38m[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)[0m 2025-09-25T09:03:14.443196+00:00 [0;38m[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)[0m 2025-09-25T09:03:14.443224+00:00 [0;38m[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)[0m 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 [1;34m[testenv] Looking for a coredump on lxc host[0m [0;94m[testenv] + ['ip', '-j', '-o', '-4', 'addr', 'show', 'dev', 'eth0'][0m [0;94m[testenv] No coredump found[0m [1;91m[testenv] s1gw unexpected exit during S1GW_Tests.TC_setup! rc=0[0m [0;94m[testenv] Waiting until test has stopped...[0m 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 [1;31m------ S1GW_Tests.TC_setup fail ------[0m
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 [1;34m[testenv] Stopping podman container[0m [0;94m[testenv] + ['podman', 'kill', 'testenv-s1gw-osmocom-nightly-20250925-0903-58f9891f-0'][0m testenv-s1gw-osmocom-nightly-20250925-0903-58f9891f-0 [1;34m[testenv] Stopping testsuite (1690931)[0m [0;94m[testenv] feed_watchdog_loop: podman container has stopped[0m [1;34m[testenv] Logs saved to: https://jenkins.osmocom.org/jenkins/job/ttcn3-s1gw-test/474/artifact/logs/ [0m + RC=1 + [ 1 = 0 ] + uptime + grep --color=always -o load.* [01;31m[Kload average: 3.33, 1.67, 1.33[m[K + exit 1 Build step 'Execute shell' marked build as failure Recording test results [Checks API] No suitable checks publisher found.
See https://jenkins.osmocom.org/jenkins/job/ttcn3-s1gw-test/475/display/redirect
Changes:
------------------------------------------ [...truncated 68.14 KiB...] 2025-09-26T09:03:14.606908+00:00 [1;37m[info] <0.469.0> Supervisor: {local,kernel_sup}. Started: id=rex,pid=<0.480.0>. (supervisor:report_progress/3:2135)[0m 2025-09-26T09:03:14.606946+00:00 [1;37m[info] <0.469.0> Supervisor: {local,kernel_sup}. Started: id=global_name_server,pid=<0.482.0>. (supervisor:report_progress/3:2135)[0m 2025-09-26T09:03:14.606975+00:00 [1;37m[info] <0.485.0> Supervisor: {local,net_sup}. Started: id=erl_epmd,pid=<0.486.0>. (supervisor:report_progress/3:2135)[0m 2025-09-26T09:03:14.606985+00:00 [1;37m[info] <0.485.0> Supervisor: {local,net_sup}. Started: id=auth,pid=<0.487.0>. (supervisor:report_progress/3:2135)[0m 2025-09-26T09:03:14.607192+00:00 [1;37m[info] <0.485.0> Supervisor: {local,net_sup}. Started: id=net_kernel,pid=<0.488.0>. (supervisor:report_progress/3:2135)[0m 2025-09-26T09:03:14.607205+00:00 [1;37m[info] <0.469.0> Supervisor: {local,kernel_sup}. Started: id=net_sup,pid=<0.485.0>. (supervisor:report_progress/3:2135)[0m 2025-09-26T09:03:14.607220+00:00 [1;37m[info] <0.469.0> Supervisor: {local,kernel_sup}. Started: id=global_group,pid=<0.491.0>. (supervisor:report_progress/3:2135)[0m 2025-09-26T09:03:14.607231+00:00 [1;37m[info] <0.469.0> Supervisor: {local,kernel_sup}. Started: id=erl_signal_server,pid=<0.493.0>. (supervisor:report_progress/3:2135)[0m 2025-09-26T09:03:14.607289+00:00 [1;37m[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)[0m 2025-09-26T09:03:14.607299+00:00 [1;37m[info] <0.469.0> Supervisor: {local,kernel_sup}. Started: id=user,pid=<0.494.0>. (supervisor:report_progress/3:2135)[0m 2025-09-26T09:03:14.607315+00:00 [1;37m[info] <0.498.0> Supervisor: {local,logger_sup}. Started: id=logger_handler_watcher,pid=<0.499.0>. (supervisor:report_progress/3:2135)[0m 2025-09-26T09:03:14.607345+00:00 [1;37m[info] <0.498.0> Supervisor: {local,logger_sup}. Started: id=logger_proxy,pid=<0.500.0>. (supervisor:report_progress/3:2135)[0m 2025-09-26T09:03:14.607351+00:00 [1;37m[info] <0.469.0> Supervisor: {local,kernel_sup}. Started: id=logger_sup,pid=<0.498.0>. (supervisor:report_progress/3:2135)[0m 2025-09-26T09:03:14.607366+00:00 [1;37m[info] <0.469.0> Supervisor: {local,kernel_sup}. Started: id=kernel_config,pid=<0.501.0>. (supervisor:report_progress/3:2135)[0m 2025-09-26T09:03:14.608409+00:00 [1;37m[info] <0.464.0> Simple handler buffer full, dropped 3 messages[0m 2025-09-26T09:03:14.610988+00:00 [1;37m[info] <0.465.0> Application: kernel. Started at: 'osmo-s1gw@3cfc6852e20c'. (application_controller:info_started/2:2113)[0m 2025-09-26T09:03:14.611065+00:00 [1;37m[info] <0.465.0> Application: stdlib. Started at: 'osmo-s1gw@3cfc6852e20c'. (application_controller:info_started/2:2113)[0m 2025-09-26T09:03:14.611145+00:00 [1;37m[info] <0.465.0> Application: logger_color_formatter. Started at: 'osmo-s1gw@3cfc6852e20c'. (application_controller:info_started/2:2113)[0m 2025-09-26T09:03:14.611217+00:00 [1;37m[info] <0.465.0> Application: logger_gsmtap. Started at: 'osmo-s1gw@3cfc6852e20c'. (application_controller:info_started/2:2113)[0m 2025-09-26T09:03:14.611286+00:00 [1;37m[info] <0.465.0> Application: pfcplib. Started at: 'osmo-s1gw@3cfc6852e20c'. (application_controller:info_started/2:2113)[0m 2025-09-26T09:03:14.611356+00:00 [1;37m[info] <0.465.0> Application: xmerl. Started at: 'osmo-s1gw@3cfc6852e20c'. (application_controller:info_started/2:2113)[0m 2025-09-26T09:03:14.611426+00:00 [1;37m[info] <0.465.0> Application: jiffy. Started at: 'osmo-s1gw@3cfc6852e20c'. (application_controller:info_started/2:2113)[0m 2025-09-26T09:03:14.611491+00:00 [1;37m[info] <0.465.0> Application: enftables. Started at: 'osmo-s1gw@3cfc6852e20c'. (application_controller:info_started/2:2113)[0m 2025-09-26T09:03:14.611584+00:00 [1;37m[info] <0.510.0> Supervisor: {local,setup_sup}. Started: id=setup_srv,pid=<0.511.0>. (supervisor:report_progress/3:2135)[0m 2025-09-26T09:03:14.611686+00:00 [1;36m[notice] <0.511.0> Setup running ...[0m 2025-09-26T09:03:14.612119+00:00 [1;36m[notice] <0.511.0> Directories verified. Res = ok[0m 2025-09-26T09:03:14.612185+00:00 [1;36m[notice] <0.511.0> Setup finished processing hooks (Mode=normal)...[0m 2025-09-26T09:03:14.612245+00:00 [1;37m[info] <0.465.0> Application: setup. Started at: 'osmo-s1gw@3cfc6852e20c'. (application_controller:info_started/2:2113)[0m 2025-09-26T09:03:14.612332+00:00 [1;37m[info] <0.465.0> Application: syntax_tools. Started at: 'osmo-s1gw@3cfc6852e20c'. (application_controller:info_started/2:2113)[0m 2025-09-26T09:03:14.612377+00:00 [1;37m[info] <0.465.0> Application: parse_trans. Started at: 'osmo-s1gw@3cfc6852e20c'. (application_controller:info_started/2:2113)[0m 2025-09-26T09:03:14.612690+00:00 [1;37m[info] <0.514.0> Supervisor: {local,exometer_core_sup}. Started: id=exometer_admin,pid=<0.515.0>. (supervisor:report_progress/3:2135)[0m 2025-09-26T09:03:14.612787+00:00 [1;37m[info] <0.514.0> Supervisor: {local,exometer_core_sup}. Started: id=exometer_cache,pid=<0.516.0>. (supervisor:report_progress/3:2135)[0m 2025-09-26T09:03:14.612830+00:00 [1;37m[info] <0.514.0> Supervisor: {local,exometer_core_sup}. Started: id=exometer_report,pid=<0.517.0>. (supervisor:report_progress/3:2135)[0m 2025-09-26T09:03:14.612867+00:00 [1;37m[info] <0.514.0> Supervisor: {local,exometer_core_sup}. Started: id=exometer_report_logger_sup,pid=<0.518.0>. (supervisor:report_progress/3:2135)[0m 2025-09-26T09:03:14.612925+00:00 [1;37m[info] <0.514.0> Supervisor: {local,exometer_core_sup}. Started: id=exometer_alias,pid=<0.519.0>. (supervisor:report_progress/3:2135)[0m 2025-09-26T09:03:14.613004+00:00 [1;37m[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)[0m 2025-09-26T09:03:14.613108+00:00 [1;37m[info] <0.465.0> Application: exometer_core. Started at: 'osmo-s1gw@3cfc6852e20c'. (application_controller:info_started/2:2113)[0m 2025-09-26T09:03:14.613106+00:00 [1;37m[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)[0m 2025-09-26T09:03:14.613154+00:00 [1;37m[info] <0.465.0> Application: exometer_report_statsd. Started at: 'osmo-s1gw@3cfc6852e20c'. (application_controller:info_started/2:2113)[0m 2025-09-26T09:03:14.613192+00:00 [1;37m[info] <0.465.0> Application: compiler. Started at: 'osmo-s1gw@3cfc6852e20c'. (application_controller:info_started/2:2113)[0m 2025-09-26T09:03:14.613197+00:00 [1;37m[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)[0m 2025-09-26T09:03:14.613224+00:00 [1;37m[info] <0.465.0> Application: elli. Started at: 'osmo-s1gw@3cfc6852e20c'. (application_controller:info_started/2:2113)[0m 2025-09-26T09:03:14.613260+00:00 [0;38m[debug] <0.503.0> Supervisor: {local,kernel_safe_sup}. Started: id=inet_gethost_native_sup,pid=<0.521.0>. (supervisor:report_progress/3:2145)[0m 2025-09-26T09:03:14.613306+00:00 [1;37m[info] <0.465.0> Application: njson. Started at: 'osmo-s1gw@3cfc6852e20c'. (application_controller:info_started/2:2113)[0m 2025-09-26T09:03:14.613362+00:00 [1;37m[info] <0.465.0> Application: ndto. Started at: 'osmo-s1gw@3cfc6852e20c'. (application_controller:info_started/2:2113)[0m 2025-09-26T09:03:14.613400+00:00 [1;37m[info] <0.465.0> Application: erf. Started at: 'osmo-s1gw@3cfc6852e20c'. (application_controller:info_started/2:2113)[0m 2025-09-26T09:03:14.613460+00:00 [1;37m[info] <0.525.0> Initiating metrics (s1gw_metrics:init/0:129)[0m 2025-09-26T09:03:14.613572+00:00 [0;38m[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)[0m 2025-09-26T09:03:14.613624+00:00 [0;38m[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)[0m 2025-09-26T09:03:14.613672+00:00 [0;38m[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)[0m 2025-09-26T09:03:14.613750+00:00 [0;38m[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)[0m 2025-09-26T09:03:14.613806+00:00 [0;38m[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)[0m 2025-09-26T09:03:14.613849+00:00 [0;38m[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)[0m 2025-09-26T09:03:14.613881+00:00 [0;38m[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)[0m 2025-09-26T09:03:14.613934+00:00 [0;38m[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)[0m 2025-09-26T09:03:14.613973+00:00 [0;38m[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)[0m 2025-09-26T09:03:14.614003+00:00 [0;38m[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)[0m 2025-09-26T09:03:14.614039+00:00 [0;38m[debug] <0.517.0> subscribe_(exometer_report_statsd, [ctr,pfcp,unexpected_pdu], value, 1000, true, [{report_type,counter}], enabled) (exometer_report:subscribe_/7:1492)[0m 2025-09-26T09:03:14.614029+00:00 [1;37m[info] <0.525.0> Supervisor: {local,osmo_s1gw_sup}. Started: id=enb_registry,pid=<0.526.0>. (supervisor:report_progress/3:2135)[0m 2025-09-26T09:03:14.614081+00:00 [0;38m[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)[0m 2025-09-26T09:03:14.614112+00:00 [0;38m[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)[0m 2025-09-26T09:03:14.614138+00:00 [0;38m[debug] <0.517.0> subscribe_(exometer_report_statsd, [ctr,s1ap,proxy,exception], value, 1000, true, [{report_type,counter}], enabled) (exometer_report:subscribe_/7:1492)[0m 2025-09-26T09:03:14.614169+00:00 [0;38m[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)[0m 2025-09-26T09:03:14.614166+00:00 [1;37m[info] <0.528.0> SCTP server listening on {127,0,1,1}:36412 (sctp_server:init/1:127)[0m 2025-09-26T09:03:14.614197+00:00 [0;38m[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)[0m 2025-09-26T09:03:14.614243+00:00 [0;38m[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)[0m 2025-09-26T09:03:14.614247+00:00 [1;37m[info] <0.525.0> Supervisor: {local,osmo_s1gw_sup}. Started: id=sctp_server,pid=<0.528.0>. (supervisor:report_progress/3:2135)[0m 2025-09-26T09:03:14.614278+00:00 [0;38m[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)[0m 2025-09-26T09:03:14.614317+00:00 [0;38m[debug] <0.517.0> subscribe_(exometer_report_statsd, [gauge,pfcp,associated], value, 1000, true, [{report_type,gauge}], enabled) (exometer_report:subscribe_/7:1492)[0m 2025-09-26T09:03:14.614344+00:00 [0;38m[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)[0m 2025-09-26T09:03:14.614367+00:00 [1;37m[info] <0.529.0> PFCP peer @ {127,0,3,1} will talk to UPF @ {127,0,3,10} (pfcp_peer:init/1:177)[0m 2025-09-26T09:03:14.614371+00:00 [0;38m[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)[0m 2025-09-26T09:03:14.614417+00:00 [1;37m[info] <0.529.0> State change: connecting -> connecting (pfcp_peer:connecting/3:194)[0m 2025-09-26T09:03:14.614422+00:00 [1;37m[info] <0.525.0> Supervisor: {local,osmo_s1gw_sup}. Started: id=pfcp_peer,pid=<0.529.0>. (supervisor:report_progress/3:2135)[0m 2025-09-26T09:03:14.614454+00:00 [0;38m[debug] <0.529.0> ctr_inc([ctr,pfcp,assoc_setup_req,tx], 1) (s1gw_metrics:ctr_inc/2:160)[0m 2025-09-26T09:03:14.614483+00:00 [0;38m[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)[0m 2025-09-26T09:03:14.614501+00:00 [0;38m[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,3967866194}}} (pfcp_peer:send_pdu/3:461)[0m 2025-09-26T09:03:14.614504+00:00 [1;37m[info] <0.525.0> Supervisor: {local,osmo_s1gw_sup}. Started: id=gtpu_kpi,pid=<0.530.0>. (supervisor:report_progress/3:2135)[0m 2025-09-26T09:03:14.614515+00:00 [0;38m[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)[0m 2025-09-26T09:03:14.614553+00:00 [0;38m[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,128,213,82>> (pfcp_peer:send_data/2:441)[0m 2025-09-26T09:03:14.614571+00:00 [0;38m[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)[0m 2025-09-26T09:03:14.614660+00:00 [0;38m[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)[0m 2025-09-26T09:03:14.614722+00:00 [0;38m[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)[0m 2025-09-26T09:03:14.614770+00:00 [0;38m[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)[0m 2025-09-26T09:03:14.614804+00:00 [0;38m[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)[0m 2025-09-26T09:03:14.614717+00:00 [1;31m[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)[0m 2025-09-26T09:03:14.614835+00:00 [0;38m[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)[0m 2025-09-26T09:03:14.614869+00:00 [0;38m[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)[0m 2025-09-26T09:03:14.614847+00:00 [1;31m[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)[0m 2025-09-26T09:03:14.614896+00:00 [0;38m[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)[0m 2025-09-26T09:03:14.614924+00:00 [1;36m[notice] <0.528.0> Terminating, reason shutdown (sctp_server:terminate/2:184)[0m 2025-09-26T09:03:14.614950+00:00 [0;38m[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)[0m 2025-09-26T09:03:14.615000+00:00 [1;36m[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)[0m 2025-09-26T09:03:14.615052+00:00 [0;38m[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)[0m 2025-09-26T09:03:14.615018+00:00 [1;31m[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: 72; neighbours: (proc_lib:crash_report/4:950)[0m 2025-09-26T09:03:14.615122+00:00 [0;38m[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)[0m 2025-09-26T09:03:14.615177+00:00 [0;38m[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)[0m 2025-09-26T09:03:14.615242+00:00 [0;38m[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)[0m 2025-09-26T09:03:14.615367+00:00 [0;38m[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)[0m 2025-09-26T09:03:14.615477+00:00 [0;38m[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)[0m 2025-09-26T09:03:14.615577+00:00 [0;38m[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)[0m 2025-09-26T09:03:14.615692+00:00 [0;38m[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)[0m 2025-09-26T09:03:14.615805+00:00 [0;38m[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)[0m 2025-09-26T09:03:14.616017+00:00 [0;38m[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)[0m 2025-09-26T09:03:14.616145+00:00 [0;38m[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)[0m 2025-09-26T09:03:14.616224+00:00 [0;38m[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)[0m MTC@3cfc6852e20c: 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@3cfc6852e20c: Initializing variables, timers and ports of component type S1GW_Tests.test_CT inside testcase TC_setup. MTC@3cfc6852e20c: Component type S1GW_Tests.test_CT was initialized. MTC@3cfc6852e20c: Creating new alive PTC with component type Mutex.MutexDispCT, component name: MutexDispCT-TC_setup. HC@3cfc6852e20c: 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)@3cfc6852e20c: Initializing variables, timers and ports of component type Mutex.MutexDispCT inside testcase TC_setup. MTC@3cfc6852e20c: PTC was created. Component reference: 3, alive: yes, type: Mutex.MutexDispCT, component name: MutexDispCT-TC_setup. MTC@3cfc6852e20c: Starting function f_MutexDisp_main() on component MutexDispCT-TC_setup(3). MTC@3cfc6852e20c: Function was started. MTC@3cfc6852e20c: Creating new PTC with component type StatsD_Checker.StatsD_Checker_CT, component name: StatsDSRV-STATS. MutexDispCT-TC_setup(3)@3cfc6852e20c: Component type Mutex.MutexDispCT was initialized. MutexDispCT-TC_setup(3)@3cfc6852e20c: Starting function f_MutexDisp_main(). HC@3cfc6852e20c: 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)@3cfc6852e20c: Initializing variables, timers and ports of component type StatsD_Checker.StatsD_Checker_CT inside testcase TC_setup. MTC@3cfc6852e20c: PTC was created. Component reference: 4, alive: no, type: StatsD_Checker.StatsD_Checker_CT, component name: StatsDSRV-STATS. MTC@3cfc6852e20c: Starting function main("127.0.4.10", 8125, 5.000000) on component StatsDSRV-STATS(4). MTC@3cfc6852e20c: Function was started. MTC@3cfc6852e20c: Creating new alive PTC with component type S1AP_Server.S1AP_Server_CT, component name: S1APSRV-TC_setup. StatsDSRV-STATS(4)@3cfc6852e20c: Component type StatsD_Checker.StatsD_Checker_CT was initialized. StatsDSRV-STATS(4)@3cfc6852e20c: Starting function main("127.0.4.10", 8125, 5.000000). StatsDSRV-STATS(4)@3cfc6852e20c: Mapping port StatsDSRV-STATS(4):STATS to system:STATS. StatsDSRV-STATS(4)@3cfc6852e20c: Map operation of StatsDSRV-STATS(4):STATS to system:STATS finished. HC@3cfc6852e20c: 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)@3cfc6852e20c: Initializing variables, timers and ports of component type S1AP_Server.S1AP_Server_CT inside testcase TC_setup. MTC@3cfc6852e20c: PTC was created. Component reference: 5, alive: yes, type: S1AP_Server.S1AP_Server_CT, component name: S1APSRV-TC_setup. MTC@3cfc6852e20c: Starting function main({ local_ip := "127.0.2.10", local_port := 36412 }) on component S1APSRV-TC_setup(5). MTC@3cfc6852e20c: Function was started. MTC@3cfc6852e20c: Creating new alive PTC with component type PFCP_Emulation.PFCP_Emulation_CT, component name: PFCPEM-TC_setup. S1APSRV-TC_setup(5)@3cfc6852e20c: Component type S1AP_Server.S1AP_Server_CT was initialized. S1APSRV-TC_setup(5)@3cfc6852e20c: Starting function main({ local_ip := "127.0.2.10", local_port := 36412 }). S1APSRV-TC_setup(5)@3cfc6852e20c: Mapping port S1APSRV-TC_setup(5):S1AP to system:S1AP_CODEC_PT. S1APSRV-TC_setup(5)@3cfc6852e20c: Map operation of S1APSRV-TC_setup(5):S1AP to system:S1AP_CODEC_PT finished. S1APSRV-TC_setup(5)@3cfc6852e20c: Warning: sizes of 'struct sctp_event_subscribe': compile-time 14, kernel: 14 S1APSRV-TC_setup(5)@3cfc6852e20c: SCTP server listening on "127.0.2.10":36412 HC@3cfc6852e20c: 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)@3cfc6852e20c: Initializing variables, timers and ports of component type PFCP_Emulation.PFCP_Emulation_CT inside testcase TC_setup. MTC@3cfc6852e20c: PTC was created. Component reference: 6, alive: yes, type: PFCP_Emulation.PFCP_Emulation_CT, component name: PFCPEM-TC_setup. MTC@3cfc6852e20c: 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@3cfc6852e20c: Function was started. PFCPEM-TC_setup(6)@3cfc6852e20c: Component type PFCP_Emulation.PFCP_Emulation_CT was initialized. MTC@3cfc6852e20c: Creating new alive PTC with component type S1GW_ConnHdlr.ConnHdlr, component name: ConnHdlr-TC_setup-0. PFCPEM-TC_setup(6)@3cfc6852e20c: 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)@3cfc6852e20c: Mapping port PFCPEM-TC_setup(6):PFCP to system:PFCP. PFCPEM-TC_setup(6)@3cfc6852e20c: Map operation of PFCPEM-TC_setup(6):PFCP to system:PFCP finished. HC@3cfc6852e20c: 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)@3cfc6852e20c: Initializing variables, timers and ports of component type S1GW_ConnHdlr.ConnHdlr inside testcase TC_setup. MTC@3cfc6852e20c: PTC was created. Component reference: 7, alive: yes, type: S1GW_ConnHdlr.ConnHdlr, component name: ConnHdlr-TC_setup-0. MTC@3cfc6852e20c: Connecting ports ConnHdlr-TC_setup-0(7):STATSD_PROC and StatsDSRV-STATS(4):STATSD_PROC. ConnHdlr-TC_setup-0(7)@3cfc6852e20c: Component type S1GW_ConnHdlr.ConnHdlr was initialized. MTC@3cfc6852e20c: Connect operation on ConnHdlr-TC_setup-0(7):STATSD_PROC and StatsDSRV-STATS(4):STATSD_PROC finished. MTC@3cfc6852e20c: Connecting ports ConnHdlr-TC_setup-0(7):S1AP_CONN and S1APSRV-TC_setup(5):S1AP_CLIENT. MTC@3cfc6852e20c: Connect operation on ConnHdlr-TC_setup-0(7):S1AP_CONN and S1APSRV-TC_setup(5):S1AP_CLIENT finished. MTC@3cfc6852e20c: Connecting ports ConnHdlr-TC_setup-0(7):S1AP_PROC and S1APSRV-TC_setup(5):S1AP_PROC. MTC@3cfc6852e20c: Connect operation on ConnHdlr-TC_setup-0(7):S1AP_PROC and S1APSRV-TC_setup(5):S1AP_PROC finished. MTC@3cfc6852e20c: Connecting ports ConnHdlr-TC_setup-0(7):PFCP and PFCPEM-TC_setup(6):CLIENT. MTC@3cfc6852e20c: Connect operation on ConnHdlr-TC_setup-0(7):PFCP and PFCPEM-TC_setup(6):CLIENT finished. MTC@3cfc6852e20c: Connecting ports ConnHdlr-TC_setup-0(7):PFCP_PROC and PFCPEM-TC_setup(6):CLIENT_PROC. MTC@3cfc6852e20c: Connect operation on ConnHdlr-TC_setup-0(7):PFCP_PROC and PFCPEM-TC_setup(6):CLIENT_PROC finished. MTC@3cfc6852e20c: Connecting ports MutexDispCT-TC_setup(3):LOCK and ConnHdlr-TC_setup-0(7):LOCK. MTC@3cfc6852e20c: Connect operation on MutexDispCT-TC_setup(3):LOCK and ConnHdlr-TC_setup-0(7):LOCK finished. MTC@3cfc6852e20c: Connecting ports MutexDispCT-TC_setup(3):UNLOCK and ConnHdlr-TC_setup-0(7):UNLOCK. MTC@3cfc6852e20c: Connect operation on MutexDispCT-TC_setup(3):UNLOCK and ConnHdlr-TC_setup-0(7):UNLOCK finished. MTC@3cfc6852e20c: 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@3cfc6852e20c: Function was started. ConnHdlr-TC_setup-0(7)@3cfc6852e20c: 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 [1;34m[testenv] Looking for a coredump on lxc host[0m [0;94m[testenv] + ['ip', '-j', '-o', '-4', 'addr', 'show', 'dev', 'eth0'][0m [1;91m[testenv] Unexpected error while attempting to fetch the coredump: <urlopen error [Errno 111] Connection refused>[0m [1;91m[testenv] s1gw unexpected exit during S1GW_Tests.TC_setup! rc=0[0m [0;94m[testenv] Waiting until test has stopped...[0m StatsDSRV-STATS(4)@3cfc6852e20c: Timeout waiting for "s1gw.gauge.pfcp.associated.value" StatsDSRV-STATS(4)@3cfc6852e20c: 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)@3cfc6852e20c: Stopping testcase execution from "StatsD_Checker.ttcnpp":212 StatsDSRV-STATS(4)@3cfc6852e20c: Stopping MTC. The current test case will be terminated. MC@3cfc6852e20c: Test Component 4 has requested to stop MTC. Terminating current testcase execution. StatsDSRV-STATS(4)@3cfc6852e20c: Stopping test component execution. ConnHdlr-TC_setup-0(7)@3cfc6852e20c: Kill was requested from MC. ConnHdlr-TC_setup-0(7)@3cfc6852e20c: Terminating test component execution. MutexDispCT-TC_setup(3)@3cfc6852e20c: Kill was requested from MC. PFCPEM-TC_setup(6)@3cfc6852e20c: Kill was requested from MC. S1APSRV-TC_setup(5)@3cfc6852e20c: Kill was requested from MC. MTC@3cfc6852e20c: Stopping test component execution. PFCPEM-TC_setup(6)@3cfc6852e20c: Terminating test component execution. S1APSRV-TC_setup(5)@3cfc6852e20c: Terminating test component execution. MutexDispCT-TC_setup(3)@3cfc6852e20c: Terminating test component execution. StatsDSRV-STATS(4)@3cfc6852e20c: Function main was stopped. PTC terminates. StatsDSRV-STATS(4)@3cfc6852e20c: Terminating component type StatsD_Checker.StatsD_Checker_CT. S1APSRV-TC_setup(5)@3cfc6852e20c: Function main was stopped. PTC terminates. ConnHdlr-TC_setup-0(7)@3cfc6852e20c: Function f_ConnHdlr_init was stopped. PTC terminates. MutexDispCT-TC_setup(3)@3cfc6852e20c: Function f_MutexDisp_main was stopped. PTC terminates. PFCPEM-TC_setup(6)@3cfc6852e20c: Function main was stopped. PTC terminates. S1APSRV-TC_setup(5)@3cfc6852e20c: Terminating component type S1AP_Server.S1AP_Server_CT. MTC@3cfc6852e20c: Terminating component type S1GW_Tests.test_CT. MutexDispCT-TC_setup(3)@3cfc6852e20c: Terminating component type Mutex.MutexDispCT. ConnHdlr-TC_setup-0(7)@3cfc6852e20c: Terminating component type S1GW_ConnHdlr.ConnHdlr. PFCPEM-TC_setup(6)@3cfc6852e20c: Terminating component type PFCP_Emulation.PFCP_Emulation_CT. StatsDSRV-STATS(4)@3cfc6852e20c: Component type StatsD_Checker.StatsD_Checker_CT was shut down inside testcase TC_setup. MTC@3cfc6852e20c: Component type S1GW_Tests.test_CT was shut down inside testcase TC_setup. MutexDispCT-TC_setup(3)@3cfc6852e20c: Component type Mutex.MutexDispCT was shut down inside testcase TC_setup. StatsDSRV-STATS(4)@3cfc6852e20c: Final verdict of PTC: fail reason: ""StatsD_Checker.ttcnpp:212 : Timeout waiting for metrics: { { name := "s1gw.gauge.pfcp.associated.value", mtype := "g" } }{ false }"" MutexDispCT-TC_setup(3)@3cfc6852e20c: Final verdict of PTC: none S1APSRV-TC_setup(5)@3cfc6852e20c: Component type S1AP_Server.S1AP_Server_CT was shut down inside testcase TC_setup. S1APSRV-TC_setup(5)@3cfc6852e20c: Final verdict of PTC: none PFCPEM-TC_setup(6)@3cfc6852e20c: Component type PFCP_Emulation.PFCP_Emulation_CT was shut down inside testcase TC_setup. PFCPEM-TC_setup(6)@3cfc6852e20c: Final verdict of PTC: none ConnHdlr-TC_setup-0(7)@3cfc6852e20c: Component type S1GW_ConnHdlr.ConnHdlr was shut down inside testcase TC_setup. ConnHdlr-TC_setup-0(7)@3cfc6852e20c: Final verdict of PTC: none MTC@3cfc6852e20c: Setting final verdict of the test case. MTC@3cfc6852e20c: Local verdict of MTC: none MTC@3cfc6852e20c: Local verdict of PTC MutexDispCT-TC_setup(3): none (none -> none) MTC@3cfc6852e20c: 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@3cfc6852e20c: Local verdict of PTC S1APSRV-TC_setup(5): none (fail -> fail) MTC@3cfc6852e20c: Local verdict of PTC PFCPEM-TC_setup(6): none (fail -> fail) MTC@3cfc6852e20c: Local verdict of PTC ConnHdlr-TC_setup-0(7): none (fail -> fail) MTC@3cfc6852e20c: Starting external command `https://jenkins.osmocom.org/jenkins/job/ttcn3-s1gw-test/ws/ttcn3-tcpdump-stop.sh S1GW_Tests.TC_setup fail'. Fri Sep 26 09:03:20 UTC 2025 [1;31m------ S1GW_Tests.TC_setup fail ------[0m
Waiting for packet dumper to finish... 0 (prev_count=-1, count=4080) MTC@3cfc6852e20c: 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@3cfc6852e20c: 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 ------ Fri Sep 26 09:03:21 UTC 2025 /usr/bin/dumpcap -q -s 1520 -n -i any -w "https://jenkins.osmocom.org/jenkins/job/ttcn3-s1gw-test/475/artifact/logs/testsuite/S1GW_Tests.TC_setup_multi.pcap" >https://jenkins.osmocom.org/jenkins/job/ttcn3-s1gw-test/475/artifact/logs/testsuite/S1GW_Tests.TC_setup_multi.pcap.stdout 2>/tmp/cmderr & Waiting for packet dumper to start... 0 [1;34m[testenv] Stopping podman container[0m [0;94m[testenv] + ['podman', 'kill', 'testenv-s1gw-osmocom-nightly-20250926-0903-571e6c26-0'][0m testenv-s1gw-osmocom-nightly-20250926-0903-571e6c26-0 [1;34m[testenv] Stopping testsuite (855371)[0m [0;94m[testenv] feed_watchdog_loop: podman container has stopped[0m [1;34m[testenv] Logs saved to: https://jenkins.osmocom.org/jenkins/job/ttcn3-s1gw-test/475/artifact/logs/ [0m + RC=1 + [ 1 = 0 ] + grep --color=always -o load.* + uptime [01;31m[Kload average: 2.35, 1.34, 1.18[m[K + exit 1 Build step 'Execute shell' marked build as failure Recording test results [Checks API] No suitable checks publisher found.
See https://jenkins.osmocom.org/jenkins/job/ttcn3-s1gw-test/476/display/redirect
Changes:
------------------------------------------ [...truncated 68.14 KiB...] 2025-09-27T09:03:20.495866+00:00 [1;37m[info] <0.469.0> Supervisor: {local,kernel_sup}. Started: id=rex,pid=<0.480.0>. (supervisor:report_progress/3:2135)[0m 2025-09-27T09:03:20.495961+00:00 [1;37m[info] <0.469.0> Supervisor: {local,kernel_sup}. Started: id=global_name_server,pid=<0.482.0>. (supervisor:report_progress/3:2135)[0m 2025-09-27T09:03:20.496046+00:00 [1;37m[info] <0.485.0> Supervisor: {local,net_sup}. Started: id=erl_epmd,pid=<0.486.0>. (supervisor:report_progress/3:2135)[0m 2025-09-27T09:03:20.496074+00:00 [1;37m[info] <0.485.0> Supervisor: {local,net_sup}. Started: id=auth,pid=<0.487.0>. (supervisor:report_progress/3:2135)[0m 2025-09-27T09:03:20.496580+00:00 [1;37m[info] <0.485.0> Supervisor: {local,net_sup}. Started: id=net_kernel,pid=<0.488.0>. (supervisor:report_progress/3:2135)[0m 2025-09-27T09:03:20.496606+00:00 [1;37m[info] <0.469.0> Supervisor: {local,kernel_sup}. Started: id=net_sup,pid=<0.485.0>. (supervisor:report_progress/3:2135)[0m 2025-09-27T09:03:20.496651+00:00 [1;37m[info] <0.469.0> Supervisor: {local,kernel_sup}. Started: id=global_group,pid=<0.491.0>. (supervisor:report_progress/3:2135)[0m 2025-09-27T09:03:20.496679+00:00 [1;37m[info] <0.469.0> Supervisor: {local,kernel_sup}. Started: id=erl_signal_server,pid=<0.493.0>. (supervisor:report_progress/3:2135)[0m 2025-09-27T09:03:20.496779+00:00 [1;37m[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)[0m 2025-09-27T09:03:20.496801+00:00 [1;37m[info] <0.469.0> Supervisor: {local,kernel_sup}. Started: id=user,pid=<0.494.0>. (supervisor:report_progress/3:2135)[0m 2025-09-27T09:03:20.496825+00:00 [1;37m[info] <0.498.0> Supervisor: {local,logger_sup}. Started: id=logger_handler_watcher,pid=<0.499.0>. (supervisor:report_progress/3:2135)[0m 2025-09-27T09:03:20.496873+00:00 [1;37m[info] <0.498.0> Supervisor: {local,logger_sup}. Started: id=logger_proxy,pid=<0.500.0>. (supervisor:report_progress/3:2135)[0m 2025-09-27T09:03:20.496882+00:00 [1;37m[info] <0.469.0> Supervisor: {local,kernel_sup}. Started: id=logger_sup,pid=<0.498.0>. (supervisor:report_progress/3:2135)[0m 2025-09-27T09:03:20.496905+00:00 [1;37m[info] <0.469.0> Supervisor: {local,kernel_sup}. Started: id=kernel_config,pid=<0.501.0>. (supervisor:report_progress/3:2135)[0m 2025-09-27T09:03:20.499665+00:00 [1;37m[info] <0.464.0> Simple handler buffer full, dropped 3 messages[0m 2025-09-27T09:03:20.501537+00:00 [1;37m[info] <0.465.0> Application: kernel. Started at: 'osmo-s1gw@ec86b8d8a8f9'. (application_controller:info_started/2:2113)[0m 2025-09-27T09:03:20.501632+00:00 [1;37m[info] <0.465.0> Application: stdlib. Started at: 'osmo-s1gw@ec86b8d8a8f9'. (application_controller:info_started/2:2113)[0m 2025-09-27T09:03:20.501777+00:00 [1;37m[info] <0.465.0> Application: logger_color_formatter. Started at: 'osmo-s1gw@ec86b8d8a8f9'. (application_controller:info_started/2:2113)[0m 2025-09-27T09:03:20.501907+00:00 [1;37m[info] <0.465.0> Application: logger_gsmtap. Started at: 'osmo-s1gw@ec86b8d8a8f9'. (application_controller:info_started/2:2113)[0m 2025-09-27T09:03:20.501982+00:00 [1;37m[info] <0.465.0> Application: pfcplib. Started at: 'osmo-s1gw@ec86b8d8a8f9'. (application_controller:info_started/2:2113)[0m 2025-09-27T09:03:20.502075+00:00 [1;37m[info] <0.465.0> Application: xmerl. Started at: 'osmo-s1gw@ec86b8d8a8f9'. (application_controller:info_started/2:2113)[0m 2025-09-27T09:03:20.502143+00:00 [1;37m[info] <0.465.0> Application: jiffy. Started at: 'osmo-s1gw@ec86b8d8a8f9'. (application_controller:info_started/2:2113)[0m 2025-09-27T09:03:20.502272+00:00 [1;37m[info] <0.465.0> Application: enftables. Started at: 'osmo-s1gw@ec86b8d8a8f9'. (application_controller:info_started/2:2113)[0m 2025-09-27T09:03:20.502414+00:00 [1;37m[info] <0.510.0> Supervisor: {local,setup_sup}. Started: id=setup_srv,pid=<0.511.0>. (supervisor:report_progress/3:2135)[0m 2025-09-27T09:03:20.502574+00:00 [1;36m[notice] <0.511.0> Setup running ...[0m 2025-09-27T09:03:20.503558+00:00 [1;36m[notice] <0.511.0> Directories verified. Res = ok[0m 2025-09-27T09:03:20.503770+00:00 [1;36m[notice] <0.511.0> Setup finished processing hooks (Mode=normal)...[0m 2025-09-27T09:03:20.503875+00:00 [1;37m[info] <0.465.0> Application: setup. Started at: 'osmo-s1gw@ec86b8d8a8f9'. (application_controller:info_started/2:2113)[0m 2025-09-27T09:03:20.503983+00:00 [1;37m[info] <0.465.0> Application: syntax_tools. Started at: 'osmo-s1gw@ec86b8d8a8f9'. (application_controller:info_started/2:2113)[0m 2025-09-27T09:03:20.504115+00:00 [1;37m[info] <0.465.0> Application: parse_trans. Started at: 'osmo-s1gw@ec86b8d8a8f9'. (application_controller:info_started/2:2113)[0m 2025-09-27T09:03:20.505208+00:00 [1;37m[info] <0.514.0> Supervisor: {local,exometer_core_sup}. Started: id=exometer_admin,pid=<0.515.0>. (supervisor:report_progress/3:2135)[0m 2025-09-27T09:03:20.505471+00:00 [1;37m[info] <0.514.0> Supervisor: {local,exometer_core_sup}. Started: id=exometer_cache,pid=<0.516.0>. (supervisor:report_progress/3:2135)[0m 2025-09-27T09:03:20.505604+00:00 [1;37m[info] <0.514.0> Supervisor: {local,exometer_core_sup}. Started: id=exometer_report,pid=<0.517.0>. (supervisor:report_progress/3:2135)[0m 2025-09-27T09:03:20.505734+00:00 [1;37m[info] <0.514.0> Supervisor: {local,exometer_core_sup}. Started: id=exometer_report_logger_sup,pid=<0.518.0>. (supervisor:report_progress/3:2135)[0m 2025-09-27T09:03:20.505952+00:00 [1;37m[info] <0.514.0> Supervisor: {local,exometer_core_sup}. Started: id=exometer_alias,pid=<0.519.0>. (supervisor:report_progress/3:2135)[0m 2025-09-27T09:03:20.506236+00:00 [1;37m[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)[0m 2025-09-27T09:03:20.506595+00:00 [1;37m[info] <0.465.0> Application: exometer_core. Started at: 'osmo-s1gw@ec86b8d8a8f9'. (application_controller:info_started/2:2113)[0m 2025-09-27T09:03:20.506714+00:00 [1;37m[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)[0m 2025-09-27T09:03:20.506897+00:00 [1;37m[info] <0.465.0> Application: exometer_report_statsd. Started at: 'osmo-s1gw@ec86b8d8a8f9'. (application_controller:info_started/2:2113)[0m 2025-09-27T09:03:20.507065+00:00 [1;37m[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)[0m 2025-09-27T09:03:20.507344+00:00 [1;37m[info] <0.465.0> Application: compiler. Started at: 'osmo-s1gw@ec86b8d8a8f9'. (application_controller:info_started/2:2113)[0m 2025-09-27T09:03:20.507330+00:00 [0;38m[debug] <0.503.0> Supervisor: {local,kernel_safe_sup}. Started: id=inet_gethost_native_sup,pid=<0.521.0>. (supervisor:report_progress/3:2145)[0m 2025-09-27T09:03:20.507500+00:00 [1;37m[info] <0.465.0> Application: elli. Started at: 'osmo-s1gw@ec86b8d8a8f9'. (application_controller:info_started/2:2113)[0m 2025-09-27T09:03:20.507594+00:00 [1;37m[info] <0.465.0> Application: njson. Started at: 'osmo-s1gw@ec86b8d8a8f9'. (application_controller:info_started/2:2113)[0m 2025-09-27T09:03:20.507697+00:00 [1;37m[info] <0.465.0> Application: ndto. Started at: 'osmo-s1gw@ec86b8d8a8f9'. (application_controller:info_started/2:2113)[0m 2025-09-27T09:03:20.507897+00:00 [1;37m[info] <0.465.0> Application: erf. Started at: 'osmo-s1gw@ec86b8d8a8f9'. (application_controller:info_started/2:2113)[0m 2025-09-27T09:03:20.508087+00:00 [1;37m[info] <0.525.0> Initiating metrics (s1gw_metrics:init/0:129)[0m 2025-09-27T09:03:20.508359+00:00 [0;38m[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)[0m 2025-09-27T09:03:20.508475+00:00 [0;38m[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)[0m 2025-09-27T09:03:20.508717+00:00 [0;38m[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)[0m 2025-09-27T09:03:20.509005+00:00 [0;38m[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)[0m 2025-09-27T09:03:20.509155+00:00 [0;38m[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)[0m 2025-09-27T09:03:20.509260+00:00 [0;38m[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)[0m 2025-09-27T09:03:20.509348+00:00 [0;38m[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)[0m 2025-09-27T09:03:20.509406+00:00 [1;37m[info] <0.525.0> Supervisor: {local,osmo_s1gw_sup}. Started: id=enb_registry,pid=<0.526.0>. (supervisor:report_progress/3:2135)[0m 2025-09-27T09:03:20.509469+00:00 [0;38m[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)[0m 2025-09-27T09:03:20.509558+00:00 [0;38m[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)[0m 2025-09-27T09:03:20.509708+00:00 [0;38m[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)[0m 2025-09-27T09:03:20.509697+00:00 [1;37m[info] <0.528.0> SCTP server listening on {127,0,1,1}:36412 (sctp_server:init/1:127)[0m 2025-09-27T09:03:20.509775+00:00 [0;38m[debug] <0.517.0> subscribe_(exometer_report_statsd, [ctr,pfcp,unexpected_pdu], value, 1000, true, [{report_type,counter}], enabled) (exometer_report:subscribe_/7:1492)[0m 2025-09-27T09:03:20.509973+00:00 [1;37m[info] <0.525.0> Supervisor: {local,osmo_s1gw_sup}. Started: id=sctp_server,pid=<0.528.0>. (supervisor:report_progress/3:2135)[0m 2025-09-27T09:03:20.509974+00:00 [0;38m[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)[0m 2025-09-27T09:03:20.510157+00:00 [0;38m[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)[0m 2025-09-27T09:03:20.510342+00:00 [1;37m[info] <0.529.0> PFCP peer @ {127,0,3,1} will talk to UPF @ {127,0,3,10} (pfcp_peer:init/1:177)[0m 2025-09-27T09:03:20.510368+00:00 [0;38m[debug] <0.517.0> subscribe_(exometer_report_statsd, [ctr,s1ap,proxy,exception], value, 1000, true, [{report_type,counter}], enabled) (exometer_report:subscribe_/7:1492)[0m 2025-09-27T09:03:20.510518+00:00 [1;37m[info] <0.525.0> Supervisor: {local,osmo_s1gw_sup}. Started: id=pfcp_peer,pid=<0.529.0>. (supervisor:report_progress/3:2135)[0m 2025-09-27T09:03:20.510532+00:00 [0;38m[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)[0m 2025-09-27T09:03:20.510507+00:00 [1;37m[info] <0.529.0> State change: connecting -> connecting (pfcp_peer:connecting/3:194)[0m 2025-09-27T09:03:20.510668+00:00 [0;38m[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)[0m 2025-09-27T09:03:20.510666+00:00 [1;37m[info] <0.525.0> Supervisor: {local,osmo_s1gw_sup}. Started: id=gtpu_kpi,pid=<0.530.0>. (supervisor:report_progress/3:2135)[0m 2025-09-27T09:03:20.510738+00:00 [0;38m[debug] <0.529.0> ctr_inc([ctr,pfcp,assoc_setup_req,tx], 1) (s1gw_metrics:ctr_inc/2:160)[0m 2025-09-27T09:03:20.510779+00:00 [0;38m[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)[0m 2025-09-27T09:03:20.510869+00:00 [0;38m[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,3967952600}}} (pfcp_peer:send_pdu/3:461)[0m 2025-09-27T09:03:20.510888+00:00 [0;38m[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)[0m 2025-09-27T09:03:20.511055+00:00 [0;38m[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)[0m 2025-09-27T09:03:20.511038+00:00 [0;38m[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,130,38,216>> (pfcp_peer:send_data/2:441)[0m 2025-09-27T09:03:20.511172+00:00 [0;38m[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)[0m 2025-09-27T09:03:20.511356+00:00 [0;38m[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)[0m 2025-09-27T09:03:20.511462+00:00 [0;38m[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)[0m 2025-09-27T09:03:20.511581+00:00 [0;38m[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)[0m 2025-09-27T09:03:20.511738+00:00 [0;38m[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)[0m 2025-09-27T09:03:20.511475+00:00 [1;31m[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)[0m 2025-09-27T09:03:20.511827+00:00 [0;38m[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)[0m 2025-09-27T09:03:20.511929+00:00 [0;38m[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)[0m 2025-09-27T09:03:20.511942+00:00 [1;31m[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)[0m 2025-09-27T09:03:20.512083+00:00 [0;38m[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)[0m 2025-09-27T09:03:20.512142+00:00 [1;36m[notice] <0.528.0> Terminating, reason shutdown (sctp_server:terminate/2:184)[0m 2025-09-27T09:03:20.512182+00:00 [0;38m[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)[0m 2025-09-27T09:03:20.512267+00:00 [0;38m[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)[0m 2025-09-27T09:03:20.512336+00:00 [0;38m[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)[0m 2025-09-27T09:03:20.512348+00:00 [1;36m[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)[0m 2025-09-27T09:03:20.512430+00:00 [0;38m[debug] <0.517.0> subscribe_(exometer_report_statsd, [gauge,pfcp,associated], value, 1000, true, [{report_type,gauge}], enabled) (exometer_report:subscribe_/7:1492)[0m 2025-09-27T09:03:20.512498+00:00 [0;38m[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)[0m 2025-09-27T09:03:20.512598+00:00 [0;38m[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)[0m 2025-09-27T09:03:20.512454+00:00 [1;31m[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)[0m 2025-09-27T09:03:20.512856+00:00 [0;38m[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)[0m 2025-09-27T09:03:20.512978+00:00 [0;38m[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)[0m 2025-09-27T09:03:20.513078+00:00 [0;38m[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)[0m 2025-09-27T09:03:20.513179+00:00 [0;38m[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)[0m 2025-09-27T09:03:20.513261+00:00 [0;38m[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)[0m 2025-09-27T09:03:20.513321+00:00 [0;38m[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)[0m 2025-09-27T09:03:20.513385+00:00 [0;38m[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)[0m 2025-09-27T09:03:20.513440+00:00 [0;38m[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)[0m 2025-09-27T09:03:20.513503+00:00 [0;38m[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)[0m 2025-09-27T09:03:20.513562+00:00 [0;38m[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)[0m 2025-09-27T09:03:20.513647+00:00 [0;38m[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)[0m MTC@ec86b8d8a8f9: 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@ec86b8d8a8f9: Initializing variables, timers and ports of component type S1GW_Tests.test_CT inside testcase TC_setup. MTC@ec86b8d8a8f9: Component type S1GW_Tests.test_CT was initialized. MTC@ec86b8d8a8f9: Creating new alive PTC with component type Mutex.MutexDispCT, component name: MutexDispCT-TC_setup. HC@ec86b8d8a8f9: PTC was created. Component reference: 3, component type: Mutex.MutexDispCT, component name: MutexDispCT-TC_setup, testcase name: TC_setup, process id: 5109. MutexDispCT-TC_setup(3)@ec86b8d8a8f9: Initializing variables, timers and ports of component type Mutex.MutexDispCT inside testcase TC_setup. MTC@ec86b8d8a8f9: PTC was created. Component reference: 3, alive: yes, type: Mutex.MutexDispCT, component name: MutexDispCT-TC_setup. MTC@ec86b8d8a8f9: Starting function f_MutexDisp_main() on component MutexDispCT-TC_setup(3). MTC@ec86b8d8a8f9: Function was started. MTC@ec86b8d8a8f9: Creating new PTC with component type StatsD_Checker.StatsD_Checker_CT, component name: StatsDSRV-STATS. MutexDispCT-TC_setup(3)@ec86b8d8a8f9: Component type Mutex.MutexDispCT was initialized. MutexDispCT-TC_setup(3)@ec86b8d8a8f9: Starting function f_MutexDisp_main(). HC@ec86b8d8a8f9: PTC was created. Component reference: 4, component type: StatsD_Checker.StatsD_Checker_CT, component name: StatsDSRV-STATS, testcase name: TC_setup, process id: 5110. StatsDSRV-STATS(4)@ec86b8d8a8f9: Initializing variables, timers and ports of component type StatsD_Checker.StatsD_Checker_CT inside testcase TC_setup. MTC@ec86b8d8a8f9: PTC was created. Component reference: 4, alive: no, type: StatsD_Checker.StatsD_Checker_CT, component name: StatsDSRV-STATS. MTC@ec86b8d8a8f9: Starting function main("127.0.4.10", 8125, 5.000000) on component StatsDSRV-STATS(4). MTC@ec86b8d8a8f9: Function was started. MTC@ec86b8d8a8f9: Creating new alive PTC with component type S1AP_Server.S1AP_Server_CT, component name: S1APSRV-TC_setup. StatsDSRV-STATS(4)@ec86b8d8a8f9: Component type StatsD_Checker.StatsD_Checker_CT was initialized. StatsDSRV-STATS(4)@ec86b8d8a8f9: Starting function main("127.0.4.10", 8125, 5.000000). StatsDSRV-STATS(4)@ec86b8d8a8f9: Mapping port StatsDSRV-STATS(4):STATS to system:STATS. StatsDSRV-STATS(4)@ec86b8d8a8f9: Map operation of StatsDSRV-STATS(4):STATS to system:STATS finished. HC@ec86b8d8a8f9: PTC was created. Component reference: 5, component type: S1AP_Server.S1AP_Server_CT, component name: S1APSRV-TC_setup, testcase name: TC_setup, process id: 5111. S1APSRV-TC_setup(5)@ec86b8d8a8f9: Initializing variables, timers and ports of component type S1AP_Server.S1AP_Server_CT inside testcase TC_setup. MTC@ec86b8d8a8f9: PTC was created. Component reference: 5, alive: yes, type: S1AP_Server.S1AP_Server_CT, component name: S1APSRV-TC_setup. MTC@ec86b8d8a8f9: Starting function main({ local_ip := "127.0.2.10", local_port := 36412 }) on component S1APSRV-TC_setup(5). MTC@ec86b8d8a8f9: Function was started. MTC@ec86b8d8a8f9: Creating new alive PTC with component type PFCP_Emulation.PFCP_Emulation_CT, component name: PFCPEM-TC_setup. S1APSRV-TC_setup(5)@ec86b8d8a8f9: Component type S1AP_Server.S1AP_Server_CT was initialized. S1APSRV-TC_setup(5)@ec86b8d8a8f9: Starting function main({ local_ip := "127.0.2.10", local_port := 36412 }). S1APSRV-TC_setup(5)@ec86b8d8a8f9: Mapping port S1APSRV-TC_setup(5):S1AP to system:S1AP_CODEC_PT. S1APSRV-TC_setup(5)@ec86b8d8a8f9: Map operation of S1APSRV-TC_setup(5):S1AP to system:S1AP_CODEC_PT finished. S1APSRV-TC_setup(5)@ec86b8d8a8f9: Warning: sizes of 'struct sctp_event_subscribe': compile-time 14, kernel: 14 S1APSRV-TC_setup(5)@ec86b8d8a8f9: SCTP server listening on "127.0.2.10":36412 HC@ec86b8d8a8f9: PTC was created. Component reference: 6, component type: PFCP_Emulation.PFCP_Emulation_CT, component name: PFCPEM-TC_setup, testcase name: TC_setup, process id: 5112. MTC@ec86b8d8a8f9: PTC was created. Component reference: 6, alive: yes, type: PFCP_Emulation.PFCP_Emulation_CT, component name: PFCPEM-TC_setup. PFCPEM-TC_setup(6)@ec86b8d8a8f9: Initializing variables, timers and ports of component type PFCP_Emulation.PFCP_Emulation_CT inside testcase TC_setup. MTC@ec86b8d8a8f9: 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@ec86b8d8a8f9: Function was started. MTC@ec86b8d8a8f9: Creating new alive PTC with component type S1GW_ConnHdlr.ConnHdlr, component name: ConnHdlr-TC_setup-0. PFCPEM-TC_setup(6)@ec86b8d8a8f9: Component type PFCP_Emulation.PFCP_Emulation_CT was initialized. PFCPEM-TC_setup(6)@ec86b8d8a8f9: 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)@ec86b8d8a8f9: Mapping port PFCPEM-TC_setup(6):PFCP to system:PFCP. PFCPEM-TC_setup(6)@ec86b8d8a8f9: Map operation of PFCPEM-TC_setup(6):PFCP to system:PFCP finished. HC@ec86b8d8a8f9: PTC was created. Component reference: 7, component type: S1GW_ConnHdlr.ConnHdlr, component name: ConnHdlr-TC_setup-0, testcase name: TC_setup, process id: 5113. ConnHdlr-TC_setup-0(7)@ec86b8d8a8f9: Initializing variables, timers and ports of component type S1GW_ConnHdlr.ConnHdlr inside testcase TC_setup. MTC@ec86b8d8a8f9: PTC was created. Component reference: 7, alive: yes, type: S1GW_ConnHdlr.ConnHdlr, component name: ConnHdlr-TC_setup-0. MTC@ec86b8d8a8f9: Connecting ports ConnHdlr-TC_setup-0(7):STATSD_PROC and StatsDSRV-STATS(4):STATSD_PROC. ConnHdlr-TC_setup-0(7)@ec86b8d8a8f9: Component type S1GW_ConnHdlr.ConnHdlr was initialized. MTC@ec86b8d8a8f9: Connect operation on ConnHdlr-TC_setup-0(7):STATSD_PROC and StatsDSRV-STATS(4):STATSD_PROC finished. MTC@ec86b8d8a8f9: Connecting ports ConnHdlr-TC_setup-0(7):S1AP_CONN and S1APSRV-TC_setup(5):S1AP_CLIENT. MTC@ec86b8d8a8f9: Connect operation on ConnHdlr-TC_setup-0(7):S1AP_CONN and S1APSRV-TC_setup(5):S1AP_CLIENT finished. MTC@ec86b8d8a8f9: Connecting ports ConnHdlr-TC_setup-0(7):S1AP_PROC and S1APSRV-TC_setup(5):S1AP_PROC. MTC@ec86b8d8a8f9: Connect operation on ConnHdlr-TC_setup-0(7):S1AP_PROC and S1APSRV-TC_setup(5):S1AP_PROC finished. MTC@ec86b8d8a8f9: Connecting ports ConnHdlr-TC_setup-0(7):PFCP and PFCPEM-TC_setup(6):CLIENT. MTC@ec86b8d8a8f9: Connect operation on ConnHdlr-TC_setup-0(7):PFCP and PFCPEM-TC_setup(6):CLIENT finished. MTC@ec86b8d8a8f9: Connecting ports ConnHdlr-TC_setup-0(7):PFCP_PROC and PFCPEM-TC_setup(6):CLIENT_PROC. MTC@ec86b8d8a8f9: Connect operation on ConnHdlr-TC_setup-0(7):PFCP_PROC and PFCPEM-TC_setup(6):CLIENT_PROC finished. MTC@ec86b8d8a8f9: Connecting ports MutexDispCT-TC_setup(3):LOCK and ConnHdlr-TC_setup-0(7):LOCK. MTC@ec86b8d8a8f9: Connect operation on MutexDispCT-TC_setup(3):LOCK and ConnHdlr-TC_setup-0(7):LOCK finished. MTC@ec86b8d8a8f9: Connecting ports MutexDispCT-TC_setup(3):UNLOCK and ConnHdlr-TC_setup-0(7):UNLOCK. MTC@ec86b8d8a8f9: Connect operation on MutexDispCT-TC_setup(3):UNLOCK and ConnHdlr-TC_setup-0(7):UNLOCK finished. MTC@ec86b8d8a8f9: 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@ec86b8d8a8f9: Function was started. ConnHdlr-TC_setup-0(7)@ec86b8d8a8f9: 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 [1;34m[testenv] Looking for a coredump on lxc host[0m [0;94m[testenv] + ['ip', '-j', '-o', '-4', 'addr', 'show', 'dev', 'eth0'][0m [1;91m[testenv] Unexpected error while attempting to fetch the coredump: <urlopen error [Errno 111] Connection refused>[0m [1;91m[testenv] s1gw unexpected exit during S1GW_Tests.TC_setup! rc=0[0m [0;94m[testenv] Waiting until test has stopped...[0m StatsDSRV-STATS(4)@ec86b8d8a8f9: Timeout waiting for "s1gw.gauge.pfcp.associated.value" StatsDSRV-STATS(4)@ec86b8d8a8f9: 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)@ec86b8d8a8f9: Stopping testcase execution from "StatsD_Checker.ttcnpp":212 StatsDSRV-STATS(4)@ec86b8d8a8f9: Stopping MTC. The current test case will be terminated. MC@ec86b8d8a8f9: Test Component 4 has requested to stop MTC. Terminating current testcase execution. StatsDSRV-STATS(4)@ec86b8d8a8f9: Stopping test component execution. S1APSRV-TC_setup(5)@ec86b8d8a8f9: Kill was requested from MC. ConnHdlr-TC_setup-0(7)@ec86b8d8a8f9: Kill was requested from MC. PFCPEM-TC_setup(6)@ec86b8d8a8f9: Kill was requested from MC. MutexDispCT-TC_setup(3)@ec86b8d8a8f9: Kill was requested from MC. S1APSRV-TC_setup(5)@ec86b8d8a8f9: Terminating test component execution. PFCPEM-TC_setup(6)@ec86b8d8a8f9: Terminating test component execution. MTC@ec86b8d8a8f9: Stopping test component execution. ConnHdlr-TC_setup-0(7)@ec86b8d8a8f9: Terminating test component execution. MutexDispCT-TC_setup(3)@ec86b8d8a8f9: Terminating test component execution. StatsDSRV-STATS(4)@ec86b8d8a8f9: Function main was stopped. PTC terminates. MTC@ec86b8d8a8f9: Terminating component type S1GW_Tests.test_CT. PFCPEM-TC_setup(6)@ec86b8d8a8f9: Function main was stopped. PTC terminates. S1APSRV-TC_setup(5)@ec86b8d8a8f9: Function main was stopped. PTC terminates. MutexDispCT-TC_setup(3)@ec86b8d8a8f9: Function f_MutexDisp_main was stopped. PTC terminates. PFCPEM-TC_setup(6)@ec86b8d8a8f9: Terminating component type PFCP_Emulation.PFCP_Emulation_CT. MutexDispCT-TC_setup(3)@ec86b8d8a8f9: Terminating component type Mutex.MutexDispCT. S1APSRV-TC_setup(5)@ec86b8d8a8f9: Terminating component type S1AP_Server.S1AP_Server_CT. MTC@ec86b8d8a8f9: Component type S1GW_Tests.test_CT was shut down inside testcase TC_setup. ConnHdlr-TC_setup-0(7)@ec86b8d8a8f9: Function f_ConnHdlr_init was stopped. PTC terminates. ConnHdlr-TC_setup-0(7)@ec86b8d8a8f9: Terminating component type S1GW_ConnHdlr.ConnHdlr. StatsDSRV-STATS(4)@ec86b8d8a8f9: Terminating component type StatsD_Checker.StatsD_Checker_CT. S1APSRV-TC_setup(5)@ec86b8d8a8f9: Component type S1AP_Server.S1AP_Server_CT was shut down inside testcase TC_setup. S1APSRV-TC_setup(5)@ec86b8d8a8f9: Final verdict of PTC: none MutexDispCT-TC_setup(3)@ec86b8d8a8f9: Component type Mutex.MutexDispCT was shut down inside testcase TC_setup. MutexDispCT-TC_setup(3)@ec86b8d8a8f9: Final verdict of PTC: none StatsDSRV-STATS(4)@ec86b8d8a8f9: Component type StatsD_Checker.StatsD_Checker_CT was shut down inside testcase TC_setup. StatsDSRV-STATS(4)@ec86b8d8a8f9: 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)@ec86b8d8a8f9: Component type PFCP_Emulation.PFCP_Emulation_CT was shut down inside testcase TC_setup. PFCPEM-TC_setup(6)@ec86b8d8a8f9: Final verdict of PTC: none ConnHdlr-TC_setup-0(7)@ec86b8d8a8f9: Component type S1GW_ConnHdlr.ConnHdlr was shut down inside testcase TC_setup. ConnHdlr-TC_setup-0(7)@ec86b8d8a8f9: Final verdict of PTC: none MTC@ec86b8d8a8f9: Setting final verdict of the test case. MTC@ec86b8d8a8f9: Local verdict of MTC: none MTC@ec86b8d8a8f9: Local verdict of PTC MutexDispCT-TC_setup(3): none (none -> none) MTC@ec86b8d8a8f9: 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@ec86b8d8a8f9: Local verdict of PTC S1APSRV-TC_setup(5): none (fail -> fail) MTC@ec86b8d8a8f9: Local verdict of PTC PFCPEM-TC_setup(6): none (fail -> fail) MTC@ec86b8d8a8f9: Local verdict of PTC ConnHdlr-TC_setup-0(7): none (fail -> fail) MTC@ec86b8d8a8f9: Starting external command `https://jenkins.osmocom.org/jenkins/job/ttcn3-s1gw-test/ws/ttcn3-tcpdump-stop.sh S1GW_Tests.TC_setup fail'. Sat Sep 27 09:03:26 UTC 2025 [1;31m------ S1GW_Tests.TC_setup fail ------[0m
Waiting for packet dumper to finish... 0 (prev_count=-1, count=4080) MTC@ec86b8d8a8f9: 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@ec86b8d8a8f9: 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 ------ Sat Sep 27 09:03:27 UTC 2025 /usr/bin/dumpcap -q -s 1520 -n -i any -w "https://jenkins.osmocom.org/jenkins/job/ttcn3-s1gw-test/476/artifact/logs/testsuite/S1GW_Tests.TC_setup_multi.pcap" >https://jenkins.osmocom.org/jenkins/job/ttcn3-s1gw-test/476/artifact/logs/testsuite/S1GW_Tests.TC_setup_multi.pcap.stdout 2>/tmp/cmderr & Waiting for packet dumper to start... 0 [1;34m[testenv] Stopping podman container[0m [0;94m[testenv] + ['podman', 'kill', 'testenv-s1gw-osmocom-nightly-20250927-0903-3fd70765-0'][0m testenv-s1gw-osmocom-nightly-20250927-0903-3fd70765-0 [1;34m[testenv] Stopping testsuite (3227370)[0m [0;94m[testenv] feed_watchdog_loop: podman container has stopped[0m [1;34m[testenv] Logs saved to: https://jenkins.osmocom.org/jenkins/job/ttcn3-s1gw-test/476/artifact/logs/ [0m + RC=1 + [ 1 = 0 ] + uptime + grep --color=always -o load.* [01;31m[Kload average: 9.99, 4.74, 2.41[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
-
jenkins＠lists.osmocom.org