search

travelping / ergw

erGW - Erlang implementations of GGSN or P-GW
GNU General Public License v2.0
81 stars 33 forks source link

No RADIUS Acct-Stop when Session Termination Pipeline fails earlier #438

Open mogaika opened 2 years ago

mogaika commented 2 years ago

erGW version

3.1.0-rc5

Erlang/OTP version

unrelated

Steps to reproduce

OCS-Free: disabled Radius enabled procedures: authenticate, authorize, start, stop OCS: enabled OFCS: enabled

Configure OCS server to not answer CCR-Update request and create session with small CC-Time

PGW <- CSR <- SGW
PGW -> Access-Request -> Radius
PGW <- Access-Response <- Radius
PGW -> CCR-Initial -> OCS
PGW <- CCA-Initial <- OCS
PGW -> AR-Start -> OFCS
PGW <- AA-Start <- OFCS
PGW -> Accounting-Request Start -> Radius
PGW -> CSR -> SGW
PGW <- Accounting-Response Start <- Radius

* Stop OCS Server here *

PGW -> CCR-Update -> OCS (No response)

Current behavior

PGW -> DBR (Reactivation requested) -> SGW
PGW <- DBR (Request accepted) <- SGW
PGW -> AR-Stop -> OFCS
PGW <- AR-Stop <- OFCS

No request to radius badarg error in logs:

2021-09-26T14:19:13.302570+00:00 <0.1552.0> debug: <0.1552.0>: found response: 6: Heartbeat Response(V: v1, SEID: undefined, Seq: 6): [#recovery_time_stamp{time = 3841653269}]
2021-09-26T14:19:13.302635+00:00 <0.1552.0> debug: send_request_reply: {send_req,{198,18,0,21},500,5,<<32,1,0,12,0,0,6,0,0,96,0,4,228,250,255,210>>,{pfcp,v1,heartbeat_request,undefined,6,[{recovery_time_stamp,3841654738}]},undefined,{ergw_sx_node,response,[<0.1555.0>,heartbeat]},-576460735670825553}
2021-09-26T14:19:13.302725+00:00 <0.1555.0> debug: PFCP OK Response: #{recovery_time_stamp => #recovery_time_stamp{time = 3841653269}}
2021-09-26T14:19:13.432612+00:00 <0.1552.0> debug: handle message 198.18.0.21:8805: <<32,1,0,12,0,2,92,0,0,96,0,4,228,250,250,21>>
2021-09-26T14:19:13.432747+00:00 <0.1552.0> debug: handle message 198.18.0.21:8805: Heartbeat Request(V: v1, SEID: undefined, Seq: 604): [#recovery_time_stamp{time = 3841653269}]
2021-09-26T14:19:13.432806+00:00 <0.1552.0> debug: cast HB request to <0.1555.0>
2021-09-26T14:19:13.851042+00:00 <0.1673.0> debug: handle_info: {timeout,#Ref<0.1541156830.3813933064.235777>,pfcp_timer}
2021-09-26T14:19:13.851185+00:00 <0.1555.0> debug: DP Call {pfcp,v1,session_modification_request,4208255547954808539,undefined,[{query_urr,[{urr_id,4}]}]}
2021-09-26T14:19:13.851234+00:00 <0.1552.0> debug: PrepSend: {send_req,{198,18,0,21},3000,3,undefined,{pfcp,v1,session_modification_request,4208255547954808539,undefined,[{query_urr,[{urr_id,4}]}]},undefined,{ergw_sx_node,response,[<0.1555.0>,{call,{<0.1673.0>,#Ref<0.1541156830.3813933061.237678>}}]},-576460735121654683}
2021-09-26T14:19:13.851332+00:00 <0.1552.0> debug: PrepSend: Session Modification Request(V: v1, SEID: 4208255547954808539, Seq: 7): [#query_urr{group = [#urr_id{id = 4}]}]
2021-09-26T14:19:13.887084+00:00 <0.1552.0> debug: handle message 198.18.0.21:8805: <<33,53,0,163,58,102,186,31,227,233,198,219,0,0,7,0,0,19,0,1,1,0,78,0,142,0,81,0,4,0,0,0,4,0,104,0,4,0,0,0,0,0,63,0,3,128,0,0,0,75,0,4,228,250,255,210,0,76,0,4,228,250,255,225,0,66,0,49,63,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,67,0,4,0,0,0,15,128,3,0,10,72,249,228,250,255,225,226,250,52,0,128,4,0,10,72,249,228,250,255,210,226,248,112,0,128,5,0,10,72,249,228,250,255,225,226,248,112,0>>
2021-09-26T14:19:13.887862+00:00 <0.1552.0> debug: handle message 198.18.0.21:8805: Session Modification Response(V: v1, SEID: 4208255547954808539, Seq: 7): [#pfcp_cause{cause = 'Request accepted'}, #usage_report_smr{, group =, #{duration_measurement => #duration_measurement{duration = 15}, end_time => #end_time{time = 3841654753}, start_time => #start_time{time = 3841654738}, tp_now => #tp_now{seconds = 3841654753,fraction = 3808048128}, tp_start_time =>, #tp_start_time{seconds = 3841654738,fraction = 3807932416}, tp_stop_time =>, #tp_stop_time{seconds = 3841654753,fraction = 3807932416}, ur_seqn => #ur_seqn{number = 0}, urr_id => #urr_id{id = 4}, usage_report_trigger =>, #usage_report_trigger{, immer = 1,droth = 0,stopt = 0,start = 0,quhti = 0, timth = 0,volth = 0,perio = 0,eveth = 0,macar = 0, envcl = 0,monit = 0,termr = 0,liusa = 0,timqu = 0, volqu = 0,emrre = 0,quvti = 0,ipmjl = 0,tebur = 0, evequ = 0}, volume_measurement =>, #volume_measurement{, total = 0,uplink = 0,downlink = 0,total_pkts = 0, uplink_pkts = 0,downlink_pkts = 0}}}]
2021-09-26T14:19:13.888986+00:00 <0.1552.0> debug: <0.1552.0>: found response: 7: Session Modification Response(V: v1, SEID: 4208255547954808539, Seq: 7): [#pfcp_cause{cause = 'Request accepted'}, #usage_report_smr{, group =, #{duration_measurement => #duration_measurement{duration = 15}, end_time => #end_time{time = 3841654753}, start_time => #start_time{time = 3841654738}, tp_now => #tp_now{seconds = 3841654753,fraction = 3808048128}, tp_start_time =>, #tp_start_time{seconds = 3841654738,fraction = 3807932416}, tp_stop_time =>, #tp_stop_time{seconds = 3841654753,fraction = 3807932416}, ur_seqn => #ur_seqn{number = 0}, urr_id => #urr_id{id = 4}, usage_report_trigger =>, #usage_report_trigger{, immer = 1,droth = 0,stopt = 0,start = 0,quhti = 0, timth = 0,volth = 0,perio = 0,eveth = 0,macar = 0, envcl = 0,monit = 0,termr = 0,liusa = 0,timqu = 0, volqu = 0,emrre = 0,quvti = 0,ipmjl = 0,tebur = 0, evequ = 0}, volume_measurement =>, #volume_measurement{, total = 0,uplink = 0,downlink = 0,total_pkts = 0, uplink_pkts = 0,downlink_pkts = 0}}}]
2021-09-26T14:19:13.890212+00:00 <0.1552.0> debug: send_request_reply: {send_req,{198,18,0,21},3000,3,<<33,52,0,24,58,102,186,31,227,233,198,219,0,0,7,0,0,77,0,8,0,81,0,4,0,0,0,4>>,{pfcp,v1,session_modification_request,4208255547954808539,7,[{query_urr,[{urr_id,4}]}]},undefined,{ergw_sx_node,response,[<0.1555.0>,{call,{<0.1673.0>,#Ref<0.1541156830.3813933061.237678>}}]},-576460735121654683}
2021-09-26T14:19:13.891276+00:00 <0.1674.0> warning: Ro Charging Key: 3000
2021-09-26T14:19:18.303210+00:00 <0.1555.0> debug: sending heartbeat
2021-09-26T14:19:18.303417+00:00 <0.1552.0> debug: PrepSend: {send_req,{198,18,0,21},500,5,undefined,{pfcp,v1,heartbeat_request,undefined,undefined,[{recovery_time_stamp,3841654738}]},undefined,{ergw_sx_node,response,[<0.1555.0>,heartbeat]},-576460730669483444}
2021-09-26T14:19:18.303624+00:00 <0.1552.0> debug: PrepSend: Heartbeat Request(V: v1, SEID: undefined, Seq: 8): [#recovery_time_stamp{time = 3841654738}]
2021-09-26T14:19:18.304270+00:00 <0.1552.0> debug: handle message 198.18.0.21:8805: <<32,2,0,12,0,0,8,0,0,96,0,4,228,250,250,21>>
2021-09-26T14:19:18.304631+00:00 <0.1552.0> debug: handle message 198.18.0.21:8805: Heartbeat Response(V: v1, SEID: undefined, Seq: 8): [#recovery_time_stamp{time = 3841653269}]
2021-09-26T14:19:18.304847+00:00 <0.1552.0> debug: <0.1552.0>: found response: 8: Heartbeat Response(V: v1, SEID: undefined, Seq: 8): [#recovery_time_stamp{time = 3841653269}]
2021-09-26T14:19:18.305083+00:00 <0.1552.0> debug: send_request_reply: {send_req,{198,18,0,21},500,5,<<32,1,0,12,0,0,8,0,0,96,0,4,228,250,255,210>>,{pfcp,v1,heartbeat_request,undefined,8,[{recovery_time_stamp,3841654738}]},undefined,{ergw_sx_node,response,[<0.1555.0>,heartbeat]},-576460730669483444}
2021-09-26T14:19:18.305463+00:00 <0.1555.0> debug: PFCP OK Response: #{recovery_time_stamp => #recovery_time_stamp{time = 3841653269}}
2021-09-26T14:19:18.314262+00:00 <0.1552.0> debug: handle message 198.18.0.21:8805: <<32,1,0,12,0,2,93,0,0,96,0,4,228,250,250,21>>
2021-09-26T14:19:18.314509+00:00 <0.1552.0> debug: handle message 198.18.0.21:8805: Heartbeat Request(V: v1, SEID: undefined, Seq: 605): [#recovery_time_stamp{time = 3841653269}]
2021-09-26T14:19:18.314738+00:00 <0.1552.0> debug: cast HB request to <0.1555.0>
2021-09-26T14:19:18.893214+00:00 <0.1955.0> debug: DIAMETER error in ergw_aaa_ro with: {error,timeout}. Request: ['CCR'|#{'3GPP-IMSI' => [<<"001010123456001">>],'Auth-Application-Id' => 4,'CC-Request-Number' => 1,'CC-Request-Type' => 2,'Destination-Realm' => <<"gy.test.cennso.net">>,'Event-Timestamp' => [{{2021,9,26},{14,19,13}}],'Multiple-Services-Credit-Control' => [#{'Rating-Group' => [3000],'Requested-Service-Unit' => #{},'Used-Service-Unit' => [#{'CC-Input-Octets' => [0],'CC-Output-Octets' => [0],'CC-Time' => [15],'CC-Total-Octets' => [0],'Reporting-Reason' => [4]}]}],'Multiple-Services-Indicator' => [1],'Service-Context-Id' => "14.32251@3gpp.org",'Service-Information' => [#{'PS-Information' => [#{'3GPP-Charging-Id' => [3615480409],'3GPP-GGSN-MCC-MNC' => [<<"001001">>],'3GPP-IMSI-MCC-MNC' => [<<"00101">>],'3GPP-MS-TimeZone' => [<<0,0>>],'3GPP-NSAPI' => [<<"5">>],'3GPP-PDP-Type' => [0],'3GPP-RAT-Type' => [<<6>>],'3GPP-SGSN-MCC-MNC' => [<<"001030">>],'3GPP-Selection-Mode' => [<<"0">>],'Called-Station-Id' => [<<"test.apn.net">>],'Charging-Characteristics-Selection-Mode' => [3],'GGSN-Address' => [{198,18,0,11}],'Node-Id' => [<<"pgw.test.cennso.net">>],'PDN-Connection-Charging-ID' => [3615480409],'PDP-Address' => [{198,20,12,198}],'QoS-Information' => [#{'APN-Aggregate-Max-Bitrate-DL' => [0],'APN-Aggregate-Max-Bitrate-UL' => [0],'Allocation-Retention-Priority' => [#{'Pre-emption-Capability' => [1],'Pre-emption-Vulnerability' => [1],'Priority-Level' => 11}],'Guaranteed-Bitrate-DL' => [0],'Guaranteed-Bitrate-UL' => [0],'Max-Requested-Bandwidth-DL' => [0],'Max-Requested-Bandwidth-UL' => [0],'QoS-Class-Identifier' => "\t"}],'SGSN-Address' => [{198,18,0,1}],'Start-Time' => [{{2021,9,26},{14,18,58}}]}]}],'Session-Id' => <<"bdbdd6bf0640;402750498;2032701184;874096397825">>,'Subscription-Id' => [#{'Subscription-Id-Data' => <<"00496448000000">>,'Subscription-Id-Type' => 0},#{'Subscription-Id-Data' => <<"001010123456001">>,'Subscription-Id-Type' => 1}],'User-Equipment-Info' => [#{'User-Equipment-Info-Type' => 0,'User-Equipment-Info-Value' => <<"0026279000000000">>}],'User-Name' => [<<"ergw">>]}]
2021-09-26T14:19:18.893686+00:00 <0.1674.0> error: CCA Result: {error,timeout}
2021-09-26T14:19:18.893834+00:00 <0.1673.0> debug: SessionEvents: #{'Accounting-Start' => -576460750121697852,'Framed-IPv6-Pool' => <<"sgi1">>,'APN' => [<<"test">>,<<"apn">>,<<"net">>],'Framed-Pool' => <<"sgi1">>,'Service-Type' => 'Framed-User','MS-Primary-NBNS-Server' => <<127,0,0,1>>,'3GPP-RAT-Type' => 6,'3GPP-NSAPI' => 5,'3GPP-Charging-Id' => 3615480409,'Acct-Interim-Interval' => 1800,'3GPP-IMSI' => <<"001010123456001">>,'Node-Id' => <<"pgw.test.cennso.net">>,'NAS-IP-Address' => {198,18,0,11},'Username' => <<"ergw">>,'3GPP-SGSN-Address' => {198,18,0,1},'3GPP-IMSI-MCC-MNC' => {<<"001">>,<<"01">>},'3GPP-PDP-Type' => 'IPv4','GTP-Version' => v2,'Credit-Control-Failure-Handling' => continue,'3GPP-SGSN-UP-Address' => {198,18,1,1},'Called-Station-Id' => <<"test.apn.net">>,'Diameter-Session-Id' => <<"bdbdd6bf0640;402750498;2032701184;874096397825">>,'3GPP-SGSN-MCC-MNC' => {<<"001">>,<<"030">>},'Acct-Authentic' => 'RADIUS','Framed-IP-Address' => {198,20,12,198},'Password' => <<"ergw">>,'Session-Id' => 31909181945741612589014337298759978498,'Multi-Session-Id' => 31909181945741612589014337298759978497,'3GPP-MS-TimeZone' => {0,0},used_credits => [{3000,#{'CC-Input-Octets' => [0],'CC-Output-Octets' => [0],'CC-Time' => [15],'CC-Total-Octets' => [0],'Reporting-Reason' => [4]}}],'3GPP-IMEISV' => <<"0026279000000000">>,'QoS-Information' => #{'APN-Aggregate-Max-Bitrate-DL' => 0,'APN-Aggregate-Max-Bitrate-UL' => 0,'Allocation-Retention-Priority' => #{'Pre-emption-Capability' => 1,'Pre-emption-Vulnerability' => 1,'Priority-Level' => 11},'Guaranteed-Bitrate-DL' => 0,'Guaranteed-Bitrate-UL' => 0,'Max-Requested-Bandwidth-DL' => 0,'Max-Requested-Bandwidth-UL' => 0,'QoS-Class-Identifier' => 9},'CC-Session-Failover' => supported,'3GPP-MSISDN' => <<"00496448000000">>,'MS-Secondary-DNS-Server' => <<8,8,4,4>>,'MS-Primary-DNS-Server' => <<"\b\b\b\b">>,'NAS-Identifier' => <<"pgw">>,'Event-Trigger' => 18,credits => #{3000 => empty},'Calling-Station-Id' => <<"00496448000000">>,'MS-Secondary-NBNS-Server' => <<127,0,0,1>>,'3GPP-GGSN-Address' => {198,18,0,11},'Bearer-Operation' => 1,'3GPP-GGSN-MCC-MNC' => {<<"001">>,<<"001">>},'Framed-Protocol' => 'GPRS-PDP-Context','3GPP-Selection-Mode' => 0,'Offline-Charging-Profile' => #{'Default' => #{'Tariff-Time' => #{'Local-Tariff-Time' => {23,0},'Location' => <<"Etc/UTC">>}}},'Session-Start' => -576460750125564415}, Events: [{stop,{gy,timeout}}]
2021-09-26T14:19:18.894577+00:00 <0.1673.0> debug: <0.1673.0>: gtp_socket send_request to 198.18.0.1({198,18,0,1}):2123: {gtp,v2,delete_bearer_request,11010049,undefined,undefined,[],[{v2_cause,0,reactivation_requested,0,0,0,undefined},{v2_eps_bearer_id,0,5}]}
2021-09-26T14:19:18.897943+00:00 <0.1549.0> debug: handle message: {gtp,{198,18,0,1},2123,{socket,<<"epc">>,'gtp-c',<0.1549.0>},{gtp,v2,delete_bearer_response,3362194550,0,undefined,[],<<2,0,2,0,16,0>>}}
2021-09-26T14:19:18.898142+00:00 <0.1549.0> debug: <0.1549.0>: found response: {v2,0}
2021-09-26T14:19:18.898353+00:00 <0.1673.0> debug: handle gtp response: {gtp,v2,delete_bearer_response,3362194550,0,undefined,[],#{{v2_cause,0} => {v2_cause,0,request_accepted,0,0,0,undefined}}}
2021-09-26T14:19:18.898461+00:00 <0.1555.0> debug: DP Call {pfcp,v1,session_deletion_request,4208255547954808539,undefined,[]}
2021-09-26T14:19:18.898562+00:00 <0.1552.0> debug: PrepSend: {send_req,{198,18,0,21},3000,3,undefined,{pfcp,v1,session_deletion_request,4208255547954808539,undefined,[]},undefined,{ergw_sx_node,response,[<0.1555.0>,{call,{<0.1673.0>,#Ref<0.1541156830.3813933061.237701>}}]},-576460730074339216}
2021-09-26T14:19:18.898696+00:00 <0.1552.0> debug: PrepSend: Session Deletion Request(V: v1, SEID: 4208255547954808539, Seq: 9): []
2021-09-26T14:19:18.899067+00:00 <0.1552.0> debug: handle message 198.18.0.21:8805: <<33,55,2,89,58,102,186,31,227,233,198,219,0,0,9,0,0,19,0,1,1,0,79,0,142,0,81,0,4,0,0,0,1,0,104,0,4,0,0,0,0,0,63,0,3,0,8,0,0,75,0,4,228,250,255,210,0,76,0,4,228,250,255,230,0,66,0,49,63,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,67,0,4,0,0,0,20,128,3,0,10,72,249,228,250,255,230,230,31,200,0,128,4,0,10,72,249,228,250,255,210,226,248,112,0,128,5,0,10,72,249,228,250,255,230,226,248,112,0,0,79,0,142,0,81,0,4,0,0,0,2,0,104,0,4,0,0,0,0,0,63,0,3,0,8,0,0,75,0,4,228,250,255,210,0,76,0,4,228,250,255,230,0,66,0,49,63,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,67,0,4,0,0,0,20,128,3,0,10,72,249,228,250,255,230,230,31,200,0,128,4,0,10,72,249,228,250,255,210,226,248,112,0,128,5,0,10,72,249,228,250,255,230,226,248,112,0,0,79,0,142,0,81,0,4,0,0,0,3,0,104,0,4,0,0,0,0,0,63,0,3,0,8,0,0,75,0,4,228,250,255,210,0,76,0,4,228,250,255,230,0,66,0,49,63,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,67,0,4,0,0,0,20,128,3,0,10,72,249,228,250,255,230,230,31,200,0,128,4,0,10,72,249,228,250,255,210,226,248,112,0,128,5,0,10,72,249,228,250,255,230,226,248,112,0,0,79,0,142,0,81,0,4,0,0,0,4,0,104,0,4,0,0,0,1,0,63,0,3,0,8,0,0,75,0,4,228,250,255,225,0,76,0,4,228,250,255,230,0,66,0,49,63,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,67,0,4,0,0,0,5,128,3,0,10,72,249,228,250,255,230,230,31,200,0,128,4,0,10,72,249,228,250,255,225,226,248,112,0,128,5,0,10,72,249,228,250,255,230,226,248,112,0>>
2021-09-26T14:19:18.900021+00:00 <0.1552.0> debug: handle message 198.18.0.21:8805: Session Deletion Response(V: v1, SEID: 4208255547954808539, Seq: 9): [#pfcp_cause{cause = 'Request accepted'}, [#usage_report_sdr{, group =, #{duration_measurement => #duration_measurement{duration = 20}, end_time => #end_time{time = 3841654758}, start_time => #start_time{time = 3841654738}, tp_now => #tp_now{seconds = 3841654758,fraction = 3860842496}, tp_start_time =>, #tp_start_time{seconds = 3841654738,fraction = 3807932416}, tp_stop_time =>, #tp_stop_time{seconds = 3841654758,fraction = 3807932416}, ur_seqn => #ur_seqn{number = 0}, urr_id => #urr_id{id = 1}, usage_report_trigger =>, #usage_report_trigger{, immer = 0,droth = 0,stopt = 0,start = 0,quhti = 0, timth = 0,volth = 0,perio = 0,eveth = 0,macar = 0, envcl = 0,monit = 0,termr = 1,liusa = 0,timqu = 0, volqu = 0,emrre = 0,quvti = 0,ipmjl = 0,tebur = 0, evequ = 0}, volume_measurement =>, #volume_measurement{, total = 0,uplink = 0,downlink = 0,total_pkts = 0, uplink_pkts = 0,downlink_pkts = 0}}}, #usage_report_sdr{, group =, #{duration_measurement => #duration_measurement{duration = 20}, end_time => #end_time{time = 3841654758}, start_time => #start_time{time = 3841654738}, tp_now => #tp_now{seconds = 3841654758,fraction = 3860842496}, tp_start_time =>, #tp_start_time{seconds = 3841654738,fraction = 3807932416}, tp_stop_time =>, #tp_stop_time{seconds = 3841654758,fraction = 3807932416}, ur_seqn => #ur_seqn{number = 0}, urr_id => #urr_id{id = 2}, usage_report_trigger =>, #usage_report_trigger{, immer = 0,droth = 0,stopt = 0,start = 0,quhti = 0, timth = 0,volth = 0,perio = 0,eveth = 0,macar = 0, envcl = 0,monit = 0,termr = 1,liusa = 0,timqu = 0, volqu = 0,emrre = 0,quvti = 0,ipmjl = 0,tebur = 0, evequ = 0}, volume_measurement =>, #volume_measurement{, total = 0,uplink = 0,downlink = 0,total_pkts = 0, uplink_pkts = 0,downlink_pkts = 0}}}, #usage_report_sdr{, group =, #{duration_measurement => #duration_measurement{duration = 20}, end_time => #end_time{time = 3841654758}, start_time => #start_time{time = 3841654738}, tp_now => #tp_now{seconds = 3841654758,fraction = 3860842496}, tp_start_time =>, #tp_start_time{seconds = 3841654738,fraction = 3807932416}, tp_stop_time =>, #tp_stop_time{seconds = 3841654758,fraction = 3807932416}, ur_seqn => #ur_seqn{number = 0}, urr_id => #urr_id{id = 3}, usage_report_trigger =>, #usage_report_trigger{, immer = 0,droth = 0,stopt = 0,start = 0,quhti = 0, timth = 0,volth = 0,perio = 0,eveth = 0,macar = 0, envcl = 0,monit = 0,termr = 1,liusa = 0,timqu = 0, volqu = 0,emrre = 0,quvti = 0,ipmjl = 0,tebur = 0, evequ = 0}, volume_measurement =>, #volume_measurement{, total = 0,uplink = 0,downlink = 0,total_pkts = 0, uplink_pkts = 0,downlink_pkts = 0}}}, #usage_report_sdr{, group =, #{duration_measurement => #duration_measurement{duration = 5}, end_time => #end_time{time = 3841654758}, start_time => #start_time{time = 3841654753}, tp_now => #tp_now{seconds = 3841654758,fraction = 3860842496}, tp_start_time =>, #tp_start_time{seconds = 3841654753,fraction = 3807932416}, tp_stop_time =>, #tp_stop_time{seconds = 3841654758,fraction = 3807932416}, ur_seqn => #ur_seqn{number = 1}, urr_id => #urr_id{id = 4}, usage_report_trigger =>, #usage_report_trigger{, immer = 0,droth = 0,stopt = 0,start = 0,quhti = 0, timth = 0,volth = 0,perio = 0,eveth = 0,macar = 0, envcl = 0,monit = 0,termr = 1,liusa = 0,timqu = 0, volqu = 0,emrre = 0,quvti = 0,ipmjl = 0,tebur = 0, evequ = 0}, volume_measurement =>, #volume_measurement{, total = 0,uplink = 0,downlink = 0,total_pkts = 0, uplink_pkts = 0,downlink_pkts = 0}}}]]
2021-09-26T14:19:18.901390+00:00 <0.1552.0> debug: <0.1552.0>: found response: 9: Session Deletion Response(V: v1, SEID: 4208255547954808539, Seq: 9): [#pfcp_cause{cause = 'Request accepted'}, [#usage_report_sdr{, group =, #{duration_measurement => #duration_measurement{duration = 20}, end_time => #end_time{time = 3841654758}, start_time => #start_time{time = 3841654738}, tp_now => #tp_now{seconds = 3841654758,fraction = 3860842496}, tp_start_time =>, #tp_start_time{seconds = 3841654738,fraction = 3807932416}, tp_stop_time =>, #tp_stop_time{seconds = 3841654758,fraction = 3807932416}, ur_seqn => #ur_seqn{number = 0}, urr_id => #urr_id{id = 1}, usage_report_trigger =>, #usage_report_trigger{, immer = 0,droth = 0,stopt = 0,start = 0,quhti = 0, timth = 0,volth = 0,perio = 0,eveth = 0,macar = 0, envcl = 0,monit = 0,termr = 1,liusa = 0,timqu = 0, volqu = 0,emrre = 0,quvti = 0,ipmjl = 0,tebur = 0, evequ = 0}, volume_measurement =>, #volume_measurement{, total = 0,uplink = 0,downlink = 0,total_pkts = 0, uplink_pkts = 0,downlink_pkts = 0}}}, #usage_report_sdr{, group =, #{duration_measurement => #duration_measurement{duration = 20}, end_time => #end_time{time = 3841654758}, start_time => #start_time{time = 3841654738}, tp_now => #tp_now{seconds = 3841654758,fraction = 3860842496}, tp_start_time =>, #tp_start_time{seconds = 3841654738,fraction = 3807932416}, tp_stop_time =>, #tp_stop_time{seconds = 3841654758,fraction = 3807932416}, ur_seqn => #ur_seqn{number = 0}, urr_id => #urr_id{id = 2}, usage_report_trigger =>, #usage_report_trigger{, immer = 0,droth = 0,stopt = 0,start = 0,quhti = 0, timth = 0,volth = 0,perio = 0,eveth = 0,macar = 0, envcl = 0,monit = 0,termr = 1,liusa = 0,timqu = 0, volqu = 0,emrre = 0,quvti = 0,ipmjl = 0,tebur = 0, evequ = 0}, volume_measurement =>, #volume_measurement{, total = 0,uplink = 0,downlink = 0,total_pkts = 0, uplink_pkts = 0,downlink_pkts = 0}}}, #usage_report_sdr{, group =, #{duration_measurement => #duration_measurement{duration = 20}, end_time => #end_time{time = 3841654758}, start_time => #start_time{time = 3841654738}, tp_now => #tp_now{seconds = 3841654758,fraction = 3860842496}, tp_start_time =>, #tp_start_time{seconds = 3841654738,fraction = 3807932416}, tp_stop_time =>, #tp_stop_time{seconds = 3841654758,fraction = 3807932416}, ur_seqn => #ur_seqn{number = 0}, urr_id => #urr_id{id = 3}, usage_report_trigger =>, #usage_report_trigger{, immer = 0,droth = 0,stopt = 0,start = 0,quhti = 0, timth = 0,volth = 0,perio = 0,eveth = 0,macar = 0, envcl = 0,monit = 0,termr = 1,liusa = 0,timqu = 0, volqu = 0,emrre = 0,quvti = 0,ipmjl = 0,tebur = 0, evequ = 0}, volume_measurement =>, #volume_measurement{, total = 0,uplink = 0,downlink = 0,total_pkts = 0, uplink_pkts = 0,downlink_pkts = 0}}}, #usage_report_sdr{, group =, #{duration_measurement => #duration_measurement{duration = 5}, end_time => #end_time{time = 3841654758}, start_time => #start_time{time = 3841654753}, tp_now => #tp_now{seconds = 3841654758,fraction = 3860842496}, tp_start_time =>, #tp_start_time{seconds = 3841654753,fraction = 3807932416}, tp_stop_time =>, #tp_stop_time{seconds = 3841654758,fraction = 3807932416}, ur_seqn => #ur_seqn{number = 1}, urr_id => #urr_id{id = 4}, usage_report_trigger =>, #usage_report_trigger{, immer = 0,droth = 0,stopt = 0,start = 0,quhti = 0, timth = 0,volth = 0,perio = 0,eveth = 0,macar = 0, envcl = 0,monit = 0,termr = 1,liusa = 0,timqu = 0, volqu = 0,emrre = 0,quvti = 0,ipmjl = 0,tebur = 0, evequ = 0}, volume_measurement =>, #volume_measurement{, total = 0,uplink = 0,downlink = 0,total_pkts = 0, uplink_pkts = 0,downlink_pkts = 0}}}]]
2021-09-26T14:19:18.902424+00:00 <0.1552.0> debug: send_request_reply: {send_req,{198,18,0,21},3000,3,<<33,54,0,12,58,102,186,31,227,233,198,219,0,0,9,0>>,{pfcp,v1,session_deletion_request,4208255547954808539,9,[]},undefined,{ergw_sx_node,response,[<0.1555.0>,{call,{<0.1673.0>,#Ref<0.1541156830.3813933061.237701>}}]},-576460730074339216}
2021-09-26T14:19:18.902747+00:00 <0.1673.0> debug: GxSessionOpts: #{'Accounting-Start' => -576460750121697852,'Framed-IPv6-Pool' => <<"sgi1">>,'APN' => [<<"test">>,<<"apn">>,<<"net">>],'Framed-Pool' => <<"sgi1">>,'Service-Type' => 'Framed-User','MS-Primary-NBNS-Server' => <<127,0,0,1>>,'3GPP-RAT-Type' => 6,'3GPP-NSAPI' => 5,'3GPP-Charging-Id' => 3615480409,'Acct-Interim-Interval' => 1800,'3GPP-IMSI' => <<"001010123456001">>,'Node-Id' => <<"pgw.test.cennso.net">>,'NAS-IP-Address' => {198,18,0,11},'Username' => <<"ergw">>,'3GPP-SGSN-Address' => {198,18,0,1},'3GPP-IMSI-MCC-MNC' => {<<"001">>,<<"01">>},'3GPP-PDP-Type' => 'IPv4','GTP-Version' => v2,'Credit-Control-Failure-Handling' => continue,'3GPP-SGSN-UP-Address' => {198,18,1,1},'Called-Station-Id' => <<"test.apn.net">>,'Diameter-Session-Id' => <<"bdbdd6bf0640;402750498;2032701184;874096397825">>,'3GPP-SGSN-MCC-MNC' => {<<"001">>,<<"030">>},'Acct-Authentic' => 'RADIUS','Framed-IP-Address' => {198,20,12,198},'Password' => <<"ergw">>,'Session-Id' => 31909181945741612589014337298759978498,'Multi-Session-Id' => 31909181945741612589014337298759978497,'3GPP-MS-TimeZone' => {0,0},used_credits => [{3000,#{'CC-Input-Octets' => [0],'CC-Output-Octets' => [0],'CC-Time' => [15],'CC-Total-Octets' => [0],'Reporting-Reason' => [4]}}],'3GPP-IMEISV' => <<"0026279000000000">>,'QoS-Information' => #{'APN-Aggregate-Max-Bitrate-DL' => 0,'APN-Aggregate-Max-Bitrate-UL' => 0,'Allocation-Retention-Priority' => #{'Pre-emption-Capability' => 1,'Pre-emption-Vulnerability' => 1,'Priority-Level' => 11},'Guaranteed-Bitrate-DL' => 0,'Guaranteed-Bitrate-UL' => 0,'Max-Requested-Bandwidth-DL' => 0,'Max-Requested-Bandwidth-UL' => 0,'QoS-Class-Identifier' => 9},'CC-Session-Failover' => supported,'3GPP-MSISDN' => <<"00496448000000">>,'MS-Secondary-DNS-Server' => <<8,8,4,4>>,'MS-Primary-DNS-Server' => <<"\b\b\b\b">>,'NAS-Identifier' => <<"pgw">>,'Event-Trigger' => 18,credits => #{3000 => empty},'Calling-Station-Id' => <<"00496448000000">>,'MS-Secondary-NBNS-Server' => <<127,0,0,1>>,'3GPP-GGSN-Address' => {198,18,0,11},'Bearer-Operation' => 1,'3GPP-GGSN-MCC-MNC' => {<<"001">>,<<"001">>},'Framed-Protocol' => 'GPRS-PDP-Context','3GPP-Selection-Mode' => 0,'Offline-Charging-Profile' => #{'Default' => #{'Tariff-Time' => #{'Local-Tariff-Time' => {23,0},'Location' => <<"Etc/UTC">>}}},'Session-Start' => -576460750125564415}
2021-09-26T14:19:18.903686+00:00 <0.1674.0> debug: Session Stop: #{'Accounting-Start' => -576460750121697852,'Framed-IPv6-Pool' => <<"sgi1">>,'APN' => [<<"test">>,<<"apn">>,<<"net">>],'Framed-Pool' => <<"sgi1">>,'Service-Type' => 'Framed-User','MS-Primary-NBNS-Server' => <<127,0,0,1>>,'3GPP-RAT-Type' => 6,'3GPP-NSAPI' => 5,'3GPP-Charging-Id' => 3615480409,'Acct-Interim-Interval' => 1800,'3GPP-IMSI' => <<"001010123456001">>,'Node-Id' => <<"pgw.test.cennso.net">>,'OutOctets' => 0,'NAS-IP-Address' => {198,18,0,11},'Username' => <<"ergw">>,'3GPP-SGSN-Address' => {198,18,0,1},'3GPP-IMSI-MCC-MNC' => {<<"001">>,<<"01">>},'3GPP-PDP-Type' => 'IPv4','GTP-Version' => v2,'Credit-Control-Failure-Handling' => continue,'3GPP-SGSN-UP-Address' => {198,18,1,1},'Called-Station-Id' => <<"test.apn.net">>,'Diameter-Session-Id' => <<"bdbdd6bf0640;402750498;2032701184;874096397825">>,'Termination-Cause' => timeout,'3GPP-SGSN-MCC-MNC' => {<<"001">>,<<"030">>},'Acct-Authentic' => 'RADIUS','Framed-IP-Address' => {198,20,12,198},'Password' => <<"ergw">>,'Session-Id' => 31909181945741612589014337298759978498,'Multi-Session-Id' => 31909181945741612589014337298759978497,'3GPP-MS-TimeZone' => {0,0},traffic_data => [#{'3GPP-Charging-Id' => [3615480409],'3GPP-RAT-Type' => [<<6>>],'Accounting-Input-Octets' => [0],'Accounting-Output-Octets' => [0],'Change-Condition' => [0],'Change-Time' => [{{2021,9,26},{14,19,18}}],'QoS-Information' => [#{'APN-Aggregate-Max-Bitrate-DL' => 0,'APN-Aggregate-Max-Bitrate-UL' => 0,'Allocation-Retention-Priority' => #{'Pre-emption-Capability' => 1,'Pre-emption-Vulnerability' => 1,'Priority-Level' => 11},'Guaranteed-Bitrate-DL' => 0,'Guaranteed-Bitrate-UL' => 0,'Max-Requested-Bandwidth-DL' => 0,'Max-Requested-Bandwidth-UL' => 0,'QoS-Class-Identifier' => 9}]}],used_credits => [{3000,#{'CC-Input-Octets' => [0],'CC-Output-Octets' => [0],'CC-Time' => [5],'CC-Total-Octets' => [0],'Reporting-Reason' => [2]}}],'3GPP-IMEISV' => <<"0026279000000000">>,'QoS-Information' => #{'APN-Aggregate-Max-Bitrate-DL' => 0,'APN-Aggregate-Max-Bitrate-UL' => 0,'Allocation-Retention-Priority' => #{'Pre-emption-Capability' => 1,'Pre-emption-Vulnerability' => 1,'Priority-Level' => 11},'Guaranteed-Bitrate-DL' => 0,'Guaranteed-Bitrate-UL' => 0,'Max-Requested-Bandwidth-DL' => 0,'Max-Requested-Bandwidth-UL' => 0,'QoS-Class-Identifier' => 9},'CC-Session-Failover' => supported,'Accounting-Stop' => -576460730070280904,'3GPP-MSISDN' => <<"00496448000000">>,'Acct-Session-Time' => 20,'MS-Secondary-DNS-Server' => <<8,8,4,4>>,'MS-Primary-DNS-Server' => <<"\b\b\b\b">>,'NAS-Identifier' => <<"pgw">>,'Event-Trigger' => 18,credits => #{3000 => empty},service_data => [#{'3GPP-RAT-Type' => [<<6>>],'Accounting-Input-Octets' => [0],'Accounting-Output-Octets' => [0],'Change-Condition' => [0],'Change-Time' => [{{2021,9,26},{14,19,18}}],'QoS-Information' => [#{'APN-Aggregate-Max-Bitrate-DL' => 0,'APN-Aggregate-Max-Bitrate-UL' => 0,'Allocation-Retention-Priority' => #{'Pre-emption-Capability' => 1,'Pre-emption-Vulnerability' => 1,'Priority-Level' => 11},'Guaranteed-Bitrate-DL' => 0,'Guaranteed-Bitrate-UL' => 0,'Max-Requested-Bandwidth-DL' => 0,'Max-Requested-Bandwidth-UL' => 0,'QoS-Class-Identifier' => 9}],'Rating-Group' => [3000],'Time-Usage' => [20]}],'Calling-Station-Id' => <<"00496448000000">>,'MS-Secondary-NBNS-Server' => <<127,0,0,1>>,'3GPP-GGSN-Address' => {198,18,0,11},'InOctets' => 0,'Bearer-Operation' => 1,'3GPP-GGSN-MCC-MNC' => {<<"001">>,<<"001">>},'Framed-Protocol' => 'GPRS-PDP-Context','3GPP-Selection-Mode' => 0,'Offline-Charging-Profile' => #{'Default' => #{'Tariff-Time' => #{'Local-Tariff-Time' => {23,0},'Location' => <<"Etc/UTC">>}}},'Session-Start' => -576460750125564415}
2021-09-26T14:19:18.904381+00:00 <0.1963.0> error: crasher: initial call: ergw_aaa_radius:'-accounting/6-fun-0-'/0, pid: <0.1963.0>, registered_name: [], error: {badarg,[{eradius_lib,encode_value,2,[{file,"/build/_build/default/lib/eradius/src/eradius_lib.erl"},{line,196}]},{eradius_lib,encode_attribute,3,[{file,"/build/_build/default/lib/eradius/src/eradius_lib.erl"},{line,177}]},{eradius_lib,'-encode_attributes/2-fun-0-',3,[{file,"/build/_build/default/lib/eradius/src/eradius_lib.erl"},{line,143}]},{lists,foldl,3,[{file,"lists.erl"},{line,1267}]},{eradius_lib,encode_request,1,[{file,"/build/_build/default/lib/eradius/src/eradius_lib.erl"},{line,73}]},{eradius_client,send_request_loop,7,[{file,"/build/_build/default/lib/eradius/src/eradius_client.erl"},{line,246}]},{eradius_client,'-send_request/3-fun-0-',10,[{file,"/build/_build/default/lib/eradius/src/eradius_client.erl"},{line,90}]},{proc_lib,init_p,3,[{file,"proc_lib.erl"},{line,211}]}]}, ancestors: [<0.1674.0>,ergw_aaa_session_sup,ergw_aaa_sup,<0.1280.0>], message_queue_len: 0, messages: [], links: [], dictionary: [], trap_exit: false, status: running, heap_size: 2586, stack_size: 28, reductions: 692; neighbours:
2021-09-26T14:19:18.905290+00:00 <0.1674.0> error: Received DOWN information for <0.1673.0> with info normal
2021-09-26T14:19:22.636465+00:00 <0.1552.0> debug: handle message 198.18.0.21:8805: <<32,1,0,12,0,2,94,0,0,96,0,4,228,250,250,21>>

Expected behavior

Stop request to radius with mapped termination cause "req_timeout"

Config

mgumz commented 2 years ago

I rephrased the issue subject: the complaint is that in the session tear down procedure a bunch of external systems will be called:

If in an early step of that pipeline something is failing for whatever reason, the remaining steps are not called.

@mogaika is ^^ what you wanted to express?

mogaika commented 2 years ago

@mogaika is ^^ what you wanted to express?

Not sure if this issue common for all "external systems". Looking at logs I have feeling that this issue specific to radius only.

2021-09-26T14:19:18.904381+00:00 <0.1963.0> error: crasher: initial call: ergw_aaa_radius:'-accounting/6-fun-0-'/0, pid: <0.1963.0>, registered_name: [], error: {badarg,[{eradius_lib,encode_value,2,[{file,"/build/_build/default/lib/eradius/src/eradius_lib.erl"},{line,196}]},{eradius_lib,encode_attribute,3,[{file,"/build/_build/default/lib/eradius/src/eradius_lib.erl"},{line,177}]},{eradius_lib,'-encode_attributes/2-fun-0-',3,[{file,"/build/_build/default/lib/eradius/src/eradius_lib.erl"},{line,143}]},{lists,foldl,3,[{file,"lists.erl"},{line,1267}]},{eradius_lib,encode_request,1,[{file,"/build/_build/default/lib/eradius/src/eradius_lib.erl"},{line,73}]},{eradius_client,send_request_loop,7,[{file,"/build/_build/default/lib/eradius/src/eradius_client.erl"},{line,246}]},{eradius_client,'-send_request/3-fun-0-',10,[{file,"/build/_build/default/lib/eradius/src/eradius_client.erl"},{line,90}]},{proc_lib,init_p,3,[{file,"proc_lib.erl"},{line,211}]}]}, ancestors: [<0.1674.0>,ergw_aaa_session_sup,ergw_aaa_sup,<0.1280.0>], message_queue_len: 0, messages: [], links: [], dictionary: [], trap_exit: false, status: running, heap_size: 2586, stack_size: 28, reductions: 692; neighbours: