Hi all!
I have been dealing with STIR/SHAKEN for a few weeks now, and while doing some tests I have found an issue which I can't find the reason for.
The script has the following route logic:
route[HANDLE_STIRSHAKEN] {
xlog("L_INFO", "HANDLE_STIRSHAKEN - STIR/SHAKEN Logic");
if ($hdrc(Identity) == 0 ){ xlog("L_INFO", "HANDLE_STIRSHAKEN - No Identity Header -> Skipping this logic"); return; }
#Verify Call Identity xlog("L_INFO", "HANDLE_STIRSHAKEN - Identity Header: $hdr(Identity)"); $var(header_1)= $(hdr(Identity){s.select,0,.}); $var(header_2)= $(hdr(Identity){s.select,1,.}); xlog("L_INFO", "HANDLE_STIRSHAKEN - Encoded Header 1: $var(header_1)"); xlog("L_INFO", "HANDLE_STIRSHAKEN - Encoded Header 2: $var(header_2)"); xlog("L_INFO", "HANDLE_STIRSHAKEN - Decoded Header 1: $(var(header_1){s.decode.base64})"); xlog("L_INFO", "HANDLE_STIRSHAKEN - Decoded Header 2: $(var(header_2){s.decode.base64})");
xlog("L_INFO", "HANDLE_STIRSHAKEN - Parsing!"); $var(hdr_1_json_payload) = $(var(header_1){s.decode.base64}); # Header 1 xlog("L_INFO", "HANDLE_STIRSHAKEN - Parsed!");
xlog("L_INFO", "HANDLE_STIRSHAKEN - Header 1 payload = $var(hdr_1_json_payload) ");
$var(hdr_2_json_payload) = $(var(header_2){s.decode.base64}); # Header 2 jansson_get_field($var(hdr_2_json_payload), "attest", "$var(attest_value)"); jansson_get_field($var(hdr_2_json_payload), "ppt", "$var(ppt_value)"); jansson_get_field($var(hdr_2_json_payload), "typ", "$var(typ_value)"); jansson_get_field($var(hdr_2_json_payload), "x5u", "$var(x5u_value)");
xlog("L_INFO", "HANDLE_STIRSHAKEN - $var(attest_value) $var(ppt_value) $var(typ_value) $var(x5u_value) ");
}
All it does is parse the Identity header received on the initial INVITE, decodes it (it is encoded in base64) and writes some JSON values on log. Nothing serious....
As the Identity header is divided into multiple parts, separated by a ".", I get the first 2 parts in 2 private variables, as per lines:
$var(header_1)= $(hdr(Identity){s.select,0,.}); $var(header_2)= $(hdr(Identity){s.select,1,.});
Logs show correctly that both variables are populated:
May 10 09:09:42 kamailio1 kamailio[153201]: INFO: {1 10 INVITE 1-1966540@10.20.0.1} <script>: HANDLE_STIRSHAKEN - Encoded Header 1: eyJhbGciOiAiRVMyNTYiLCJwcHQiOiAic2hha2VuIiwidHlwIjogInBhc3Nwb3J0IiwieDV1IjogImh0dHBzOi8vY2VydGlmaWNh dGVzLmNsZWFyaXAuY29tL2IxNWQ3Y2M5LTBmMjYtNDZjMi04M2VhLWEzZTYzYTgyZWMzYS83Y2M0ZGI2OTVkMTNlZGFkYTRkMWY5ODYxYjliODBmZS5jcnQifQ May 10 09:09:42 kamailio1 kamailio[153201]: DEBUG: {1 10 INVITE 1-1966540@10.20.0.1} <core> [core/parser/msg_parser.c:324]: parse_headers(): flags=ffffffffffffffff May 10 09:09:42 kamailio1 kamailio[153201]: DEBUG: {1 10 INVITE 1-1966540@10.20.0.1} <core> [core/pvapi.c:1418]: pv_printf_mode(): final buffer length 34 May 10 09:09:42 kamailio1 kamailio[153201]: DEBUG: {1 10 INVITE 1-1966540@10.20.0.1} <core> [core/parser/msg_parser.c:324]: parse_headers(): flags=ffffffffffffffff May 10 09:09:42 kamailio1 kamailio[153201]: DEBUG: {1 10 INVITE 1-1966540@10.20.0.1} <core> [core/pvapi.c:1418]: pv_printf_mode(): final buffer length 34 May 10 09:09:42 kamailio1 kamailio[153201]: DEBUG: {1 10 INVITE 1-1966540@10.20.0.1} <core> [core/pvapi.c:1418]: pv_printf_mode(): final buffer length 230 May 10 09:09:42 kamailio1 kamailio[153201]: INFO: {1 10 INVITE 1-1966540@10.20.0.1} <script>: HANDLE_STIRSHAKEN - Encoded Header 2: eyJhdHRlc3QiOiAiQSIsImRlc3QiOiB7InRuIjogWyIxNDA0NTI2NjA2MCJdfSwiaWF0IjogMTU0ODg1OTk4Miwib3JpZyI6IHsi dG4iOiAiMTgwMDEyMzQ1NjcifSwib3JpZ2lkIjogIjNhNDdjYTIzLWQ3YWItNDQ2Yi04MjFkLTMzZDVkZWVkYmVkNCJ9
However, when decoding both values:
xlog("L_INFO", "HANDLE_STIRSHAKEN - Decoded Header 1: $(var(header_1){s.decode.base64})"); xlog("L_INFO", "HANDLE_STIRSHAKEN - Decoded Header 2: $(var(header_2){s.decode.base64})");
only $var(header_2) gets decoded:
May 10 09:09:42 kamailio1 kamailio[153201]: DEBUG: {1 10 INVITE 1-1966540@10.20.0.1} <core> [core/parser/msg_parser.c:324]: parse_headers(): flags=ffffffffffffffff May 10 09:09:42 kamailio1 kamailio[153201]: DEBUG: {1 10 INVITE 1-1966540@10.20.0.1} <core> [core/pvapi.c:1418]: pv_printf_mode(): final buffer length 34 May 10 09:09:42 kamailio1 kamailio[153201]: DEBUG: {1 10 INVITE 1-1966540@10.20.0.1} <core> [core/parser/msg_parser.c:324]: parse_headers(): flags=ffffffffffffffff May 10 09:09:42 kamailio1 kamailio[153201]: DEBUG: {1 10 INVITE 1-1966540@10.20.0.1} <core> [core/pvapi.c:1418]: pv_printf_mode(): final buffer length 34 May 10 09:09:42 kamailio1 kamailio[153201]: DEBUG: {1 10 INVITE 1-1966540@10.20.0.1} <core> [core/pvapi.c:1418]: pv_printf_mode(): final buffer length 38 May 10 09:09:42 kamailio1 kamailio[153201]: INFO: {1 10 INVITE 1-1966540@10.20.0.1} <script>: *HANDLE_STIRSHAKEN - Decoded Header 1:* May 10 09:09:42 kamailio1 kamailio[153201]: DEBUG: {1 10 INVITE 1-1966540@10.20.0.1} <core> [core/parser/msg_parser.c:324]: parse_headers(): flags=ffffffffffffffff May 10 09:09:42 kamailio1 kamailio[153201]: DEBUG: {1 10 INVITE 1-1966540@10.20.0.1} <core> [core/pvapi.c:1418]: pv_printf_mode(): final buffer length 34 May 10 09:09:42 kamailio1 kamailio[153201]: DEBUG: {1 10 INVITE 1-1966540@10.20.0.1} <core> [core/parser/msg_parser.c:324]: parse_headers(): flags=ffffffffffffffff May 10 09:09:42 kamailio1 kamailio[153201]: DEBUG: {1 10 INVITE 1-1966540@10.20.0.1} <core> [core/pvapi.c:1418]: pv_printf_mode(): final buffer length 34 May 10 09:09:42 kamailio1 kamailio[153201]: DEBUG: {1 10 INVITE 1-1966540@10.20.0.1} <core> [core/pvapi.c:1418]: pv_printf_mode(): final buffer length 182 May 10 09:09:42 kamailio1 kamailio[153201]: INFO: {1 10 INVITE 1-1966540@10.20.0.1} <script>: *HANDLE_STIRSHAKEN - Decoded Header 2: {"attest": "A","dest": {"tn": ["14045266060"]},"iat": 1548859982,"orig": {"tn": "18001234567"},"origid": "3a47ca23-d7ab-446b-821d-33d5deedbed4"}*
As you can veri And to ease debugging, I have isolated the line that generates the issue:
May 10 09:09:42 kamailio1 kamailio[153201]: INFO: {1 10 INVITE 1-1966540@10.20.0.1} <script>: HANDLE_STIRSHAKEN - Parsing! May 10 09:09:42 kamailio1 kamailio[153201]: DEBUG: {1 10 INVITE 1-1966540@10.20.0.1} <core> [core/parser/msg_parser.c:324]: parse_headers(): flags=ffffffffffffffff May 10 09:09:42 kamailio1 kamailio[153201]: DEBUG: {1 10 INVITE 1-1966540@10.20.0.1} <core> [core/pvapi.c:1418]: pv_printf_mode(): final buffer length 34 May 10 09:09:42 kamailio1 kamailio[153201]: DEBUG: {1 10 INVITE 1-1966540@10.20.0.1} <core> [core/parser/msg_parser.c:324]: parse_headers(): flags=ffffffffffffffff May 10 09:09:42 kamailio1 kamailio[153201]: DEBUG: {1 10 INVITE 1-1966540@10.20.0.1} <core> [core/pvapi.c:1418]: pv_printf_mode(): final buffer length 34 *May 10 09:09:42 kamailio1 kamailio[153201]: ERROR: {1 10 INVITE 1-1966540@10.20.0.1 1-1966540@10.20.0.1} <core> [core/lvalue.c:351]: lval_pvar_assign(): non existing right pvar* *May 10 09:09:42 kamailio1 kamailio[153201]: ERROR: {1 10 INVITE 1-1966540@10.20.0.1 1-1966540@10.20.0.1} <core> [core/lvalue.c:411]: lval_assign(): assignment failed at pos: (21,32-21,64)* May 10 09:09:42 kamailio1 kamailio[153201]: DEBUG: {1 10 INVITE 1-1966540@10.20.0.1} <core> [core/parser/msg_parser.c:324]: parse_headers(): flags=ffffffffffffffff May 10 09:09:42 kamailio1 kamailio[153201]: DEBUG: {1 10 INVITE 1-1966540@10.20.0.1} <core> [core/pvapi.c:1418]: pv_printf_mode(): final buffer length 34 May 10 09:09:42 kamailio1 kamailio[153201]: DEBUG: {1 10 INVITE 1-1966540@10.20.0.1} <core> [core/parser/msg_parser.c:324]: parse_headers(): flags=ffffffffffffffff May 10 09:09:42 kamailio1 kamailio[153201]: DEBUG: {1 10 INVITE 1-1966540@10.20.0.1} <core> [core/pvapi.c:1418]: pv_printf_mode(): final buffer length 34 May 10 09:09:42 kamailio1 kamailio[153201]: DEBUG: {1 10 INVITE 1-1966540@10.20.0.1} <core> [core/pvapi.c:1418]: pv_printf_mode(): final buffer length 27 May 10 09:09:42 kamailio1 kamailio[153201]: INFO: {1 10 INVITE 1-1966540@10.20.0.1} <script>: HANDLE_STIRSHAKEN - Parsed!
Even though the $var(header_1) contains a base64 encoded string, the decoder seems to fail. If I copy the value contained in $var(header_1) to an online decoder like https://www.base64decode.org/ the string gets decoded correctly.
I have even modified the line :
$var(header_1)= $(hdr(Identity){s.select,0,.});
to get the reverse index from the Identity string by doing
$var(header_1)= $(hdr(Identity){s.select,-6,.});
It gets the same encoded string, same value (as expected), but the result is the same: Kamailio's s.decode.base64 fails with the same error. i'm not sure what assignment failed at pos: (21,32-21,64) could mean....
I don't think my code is wrong, as the same function is used on $var(header_2) value and it works, but maybe someone can correct me.
Greatly appreciate your help.
Cheers,
*Sérgio Charrua*
Hi all!
Solved the issue by using s.decode.base64t instead of s.decode.base64 ...
Thanks anyway!
*Sérgio Charrua*
On Fri, May 10, 2024 at 9:40 AM Sergio Charrua sergio.charrua@voip.pt wrote:
Hi all!
I have been dealing with STIR/SHAKEN for a few weeks now, and while doing some tests I have found an issue which I can't find the reason for.
The script has the following route logic:
route[HANDLE_STIRSHAKEN] {
xlog("L_INFO", "HANDLE_STIRSHAKEN - STIR/SHAKEN Logic"); if ($hdrc(Identity) == 0 ){ xlog("L_INFO", "HANDLE_STIRSHAKEN - No Identity Header -> Skippingthis logic"); return; }
#Verify Call Identity xlog("L_INFO", "HANDLE_STIRSHAKEN - Identity Header: $hdr(Identity)"); $var(header_1)= $(hdr(Identity){s.select,0,.}); $var(header_2)= $(hdr(Identity){s.select,1,.}); xlog("L_INFO", "HANDLE_STIRSHAKEN - Encoded Header 1: $var(header_1)"); xlog("L_INFO", "HANDLE_STIRSHAKEN - Encoded Header 2: $var(header_2)"); xlog("L_INFO", "HANDLE_STIRSHAKEN - Decoded Header 1:$(var(header_1){s.decode.base64})"); xlog("L_INFO", "HANDLE_STIRSHAKEN - Decoded Header 2: $(var(header_2){s.decode.base64})");
xlog("L_INFO", "HANDLE_STIRSHAKEN - Parsing!"); $var(hdr_1_json_payload) = $(var(header_1){s.decode.base64}); # Header1 xlog("L_INFO", "HANDLE_STIRSHAKEN - Parsed!");
xlog("L_INFO", "HANDLE_STIRSHAKEN - Header 1 payload =$var(hdr_1_json_payload) ");
$var(hdr_2_json_payload) = $(var(header_2){s.decode.base64}); # Header2 jansson_get_field($var(hdr_2_json_payload), "attest", "$var(attest_value)"); jansson_get_field($var(hdr_2_json_payload), "ppt", "$var(ppt_value)"); jansson_get_field($var(hdr_2_json_payload), "typ", "$var(typ_value)"); jansson_get_field($var(hdr_2_json_payload), "x5u", "$var(x5u_value)");
xlog("L_INFO", "HANDLE_STIRSHAKEN - $var(attest_value) $var(ppt_value)$var(typ_value) $var(x5u_value) ");
}
All it does is parse the Identity header received on the initial INVITE, decodes it (it is encoded in base64) and writes some JSON values on log. Nothing serious....
As the Identity header is divided into multiple parts, separated by a ".", I get the first 2 parts in 2 private variables, as per lines:
$var(header_1)= $(hdr(Identity){s.select,0,.}); $var(header_2)= $(hdr(Identity){s.select,1,.});Logs show correctly that both variables are populated:
May 10 09:09:42 kamailio1 kamailio[153201]: INFO: {1 10 INVITE 1-1966540@10.20.0.1} <script>: HANDLE_STIRSHAKEN - Encoded Header 1: eyJhbGciOiAiRVMyNTYiLCJwcHQiOiAic2hha2VuIiwidHlwIjogInBhc3Nwb3J0IiwieDV1IjogImh0dHBzOi8vY2VydGlmaWNh dGVzLmNsZWFyaXAuY29tL2IxNWQ3Y2M5LTBmMjYtNDZjMi04M2VhLWEzZTYzYTgyZWMzYS83Y2M0ZGI2OTVkMTNlZGFkYTRkMWY5ODYxYjliODBmZS5jcnQifQ May 10 09:09:42 kamailio1 kamailio[153201]: DEBUG: {1 10 INVITE 1-1966540@10.20.0.1} <core> [core/parser/msg_parser.c:324]: parse_headers(): flags=ffffffffffffffff May 10 09:09:42 kamailio1 kamailio[153201]: DEBUG: {1 10 INVITE 1-1966540@10.20.0.1} <core> [core/pvapi.c:1418]: pv_printf_mode(): final buffer length 34 May 10 09:09:42 kamailio1 kamailio[153201]: DEBUG: {1 10 INVITE 1-1966540@10.20.0.1} <core> [core/parser/msg_parser.c:324]: parse_headers(): flags=ffffffffffffffff May 10 09:09:42 kamailio1 kamailio[153201]: DEBUG: {1 10 INVITE 1-1966540@10.20.0.1} <core> [core/pvapi.c:1418]: pv_printf_mode(): final buffer length 34 May 10 09:09:42 kamailio1 kamailio[153201]: DEBUG: {1 10 INVITE 1-1966540@10.20.0.1} <core> [core/pvapi.c:1418]: pv_printf_mode(): final buffer length 230 May 10 09:09:42 kamailio1 kamailio[153201]: INFO: {1 10 INVITE 1-1966540@10.20.0.1} <script>: HANDLE_STIRSHAKEN - Encoded Header 2: eyJhdHRlc3QiOiAiQSIsImRlc3QiOiB7InRuIjogWyIxNDA0NTI2NjA2MCJdfSwiaWF0IjogMTU0ODg1OTk4Miwib3JpZyI6IHsi dG4iOiAiMTgwMDEyMzQ1NjcifSwib3JpZ2lkIjogIjNhNDdjYTIzLWQ3YWItNDQ2Yi04MjFkLTMzZDVkZWVkYmVkNCJ9
However, when decoding both values:
xlog("L_INFO", "HANDLE_STIRSHAKEN - Decoded Header 1:$(var(header_1){s.decode.base64})"); xlog("L_INFO", "HANDLE_STIRSHAKEN - Decoded Header 2: $(var(header_2){s.decode.base64})");
only $var(header_2) gets decoded:
May 10 09:09:42 kamailio1 kamailio[153201]: DEBUG: {1 10 INVITE 1-1966540@10.20.0.1} <core> [core/parser/msg_parser.c:324]: parse_headers(): flags=ffffffffffffffff May 10 09:09:42 kamailio1 kamailio[153201]: DEBUG: {1 10 INVITE 1-1966540@10.20.0.1} <core> [core/pvapi.c:1418]: pv_printf_mode(): final buffer length 34 May 10 09:09:42 kamailio1 kamailio[153201]: DEBUG: {1 10 INVITE 1-1966540@10.20.0.1} <core> [core/parser/msg_parser.c:324]: parse_headers(): flags=ffffffffffffffff May 10 09:09:42 kamailio1 kamailio[153201]: DEBUG: {1 10 INVITE 1-1966540@10.20.0.1} <core> [core/pvapi.c:1418]: pv_printf_mode(): final buffer length 34 May 10 09:09:42 kamailio1 kamailio[153201]: DEBUG: {1 10 INVITE 1-1966540@10.20.0.1} <core> [core/pvapi.c:1418]: pv_printf_mode(): final buffer length 38 May 10 09:09:42 kamailio1 kamailio[153201]: INFO: {1 10 INVITE 1-1966540@10.20.0.1} <script>: *HANDLE_STIRSHAKEN - Decoded Header 1:* May 10 09:09:42 kamailio1 kamailio[153201]: DEBUG: {1 10 INVITE 1-1966540@10.20.0.1} <core> [core/parser/msg_parser.c:324]: parse_headers(): flags=ffffffffffffffff May 10 09:09:42 kamailio1 kamailio[153201]: DEBUG: {1 10 INVITE 1-1966540@10.20.0.1} <core> [core/pvapi.c:1418]: pv_printf_mode(): final buffer length 34 May 10 09:09:42 kamailio1 kamailio[153201]: DEBUG: {1 10 INVITE 1-1966540@10.20.0.1} <core> [core/parser/msg_parser.c:324]: parse_headers(): flags=ffffffffffffffff May 10 09:09:42 kamailio1 kamailio[153201]: DEBUG: {1 10 INVITE 1-1966540@10.20.0.1} <core> [core/pvapi.c:1418]: pv_printf_mode(): final buffer length 34 May 10 09:09:42 kamailio1 kamailio[153201]: DEBUG: {1 10 INVITE 1-1966540@10.20.0.1} <core> [core/pvapi.c:1418]: pv_printf_mode(): final buffer length 182 May 10 09:09:42 kamailio1 kamailio[153201]: INFO: {1 10 INVITE 1-1966540@10.20.0.1} <script>: *HANDLE_STIRSHAKEN - Decoded Header 2: {"attest": "A","dest": {"tn": ["14045266060"]},"iat": 1548859982,"orig": {"tn": "18001234567"},"origid": "3a47ca23-d7ab-446b-821d-33d5deedbed4"}*
As you can veri And to ease debugging, I have isolated the line that generates the issue:
May 10 09:09:42 kamailio1 kamailio[153201]: INFO: {1 10 INVITE 1-1966540@10.20.0.1} <script>: HANDLE_STIRSHAKEN - Parsing! May 10 09:09:42 kamailio1 kamailio[153201]: DEBUG: {1 10 INVITE 1-1966540@10.20.0.1} <core> [core/parser/msg_parser.c:324]: parse_headers(): flags=ffffffffffffffff May 10 09:09:42 kamailio1 kamailio[153201]: DEBUG: {1 10 INVITE 1-1966540@10.20.0.1} <core> [core/pvapi.c:1418]: pv_printf_mode(): final buffer length 34 May 10 09:09:42 kamailio1 kamailio[153201]: DEBUG: {1 10 INVITE 1-1966540@10.20.0.1} <core> [core/parser/msg_parser.c:324]: parse_headers(): flags=ffffffffffffffff May 10 09:09:42 kamailio1 kamailio[153201]: DEBUG: {1 10 INVITE 1-1966540@10.20.0.1} <core> [core/pvapi.c:1418]: pv_printf_mode(): final buffer length 34 *May 10 09:09:42 kamailio1 kamailio[153201]: ERROR: {1 10 INVITE 1-1966540@10.20.0.1 1-1966540@10.20.0.1} <core> [core/lvalue.c:351]: lval_pvar_assign(): non existing right pvar* *May 10 09:09:42 kamailio1 kamailio[153201]: ERROR: {1 10 INVITE 1-1966540@10.20.0.1 1-1966540@10.20.0.1} <core> [core/lvalue.c:411]: lval_assign(): assignment failed at pos: (21,32-21,64)* May 10 09:09:42 kamailio1 kamailio[153201]: DEBUG: {1 10 INVITE 1-1966540@10.20.0.1} <core> [core/parser/msg_parser.c:324]: parse_headers(): flags=ffffffffffffffff May 10 09:09:42 kamailio1 kamailio[153201]: DEBUG: {1 10 INVITE 1-1966540@10.20.0.1} <core> [core/pvapi.c:1418]: pv_printf_mode(): final buffer length 34 May 10 09:09:42 kamailio1 kamailio[153201]: DEBUG: {1 10 INVITE 1-1966540@10.20.0.1} <core> [core/parser/msg_parser.c:324]: parse_headers(): flags=ffffffffffffffff May 10 09:09:42 kamailio1 kamailio[153201]: DEBUG: {1 10 INVITE 1-1966540@10.20.0.1} <core> [core/pvapi.c:1418]: pv_printf_mode(): final buffer length 34 May 10 09:09:42 kamailio1 kamailio[153201]: DEBUG: {1 10 INVITE 1-1966540@10.20.0.1} <core> [core/pvapi.c:1418]: pv_printf_mode(): final buffer length 27 May 10 09:09:42 kamailio1 kamailio[153201]: INFO: {1 10 INVITE 1-1966540@10.20.0.1} <script>: HANDLE_STIRSHAKEN - Parsed!
Even though the $var(header_1) contains a base64 encoded string, the decoder seems to fail. If I copy the value contained in $var(header_1) to an online decoder like https://www.base64decode.org/ the string gets decoded correctly.
I have even modified the line :
$var(header_1)= $(hdr(Identity){s.select,0,.});
to get the reverse index from the Identity string by doing
$var(header_1)= $(hdr(Identity){s.select,-6,.});
It gets the same encoded string, same value (as expected), but the result is the same: Kamailio's s.decode.base64 fails with the same error. i'm not sure what assignment failed at pos: (21,32-21,64) could mean....
I don't think my code is wrong, as the same function is used on $var(header_2) value and it works, but maybe someone can correct me.
Greatly appreciate your help.
Cheers,
*Sérgio Charrua*
-
Sergio Charrua