Attention is currently required from: fixeria, laforge, pespin. neels has posted comments on this change. ( https://gerrit.osmocom.org/c/osmo-ttcn3-hacks/+/34415?usp=email ) Change subject: sip: tweak failure reporting for SIP messages ...................................................................... Patch Set 2: (1 comment) File sip/SIP_Tests.ttcn: https://gerrit.osmocom.org/c/osmo-ttcn3-hacks/+/34415/comment/ac33c3aa_deff… PS1, Line 195: og("FAIL: expected SIP message ", sip_expect); : setverdict(fail, "Received unexpected SIP message"); Ah interesting, thanks for log2str(), didn't know about it. I'm not sure that f_shutdown() should always dup the log in addition to setverdict(), it only makes sense for logs that contain a message dump. Maybe f_shutdown() could get args expected_msg and got_msg, and log those only when present. That would make most sense if ttcn3 could somehow output the exact reason why a msg does not match a template. (So far I just compare manually, or paste into a diff invocation, cumbersome) I like fixeria's example, f_shutdown() for shutdown only and set the verdict separately. I confirmed that a message dump in the verdict doesn't get picked up properly by logformat. I pasted below a comparison of 'log("FAIL: foo ", msg)' and 'f_shutdown(..., log2str("foo ", msg))'. log from msg dump in setverdict possibly gets mixed up because of double quotes, and it prints the msg twice, so it's very noisy: ``` 16:28:12.217318 5 Misc_Helpers.ttcn:32 setverdict(fail): none -> fail reason: ""SIP_Tests.ttcn:300 : foo { msg_type := MNCC_SETUP_REQ (257), u := { signal := { callref := 5001, bearer_cap := omit, called := { number_type := GSM48_TON_UNKNOWN (0), plan := GSM48_NUMPLAN_E164 (1), presence := GSM48_PRES_IND_ALLOWED (0), screen := GSM48_SCR_IND_NOT_SCREENED (0), number := \"98766\" }, calling := { number_type := GSM48_TON_UNKNOWN (0), plan := GSM48_NUMPLAN_E164 (1), presence := GSM48_PRES_IND_ALLOWED (0), screen := GSM48_SCR_IND_NOT_SCREENED (0), number := \"12345\" }, redirecting := omit, connected := omit, cause := omit, progress := omit, useruser := omit, facility := omit, cccap := omit, ssversion := omit, clir_sup := 0, clir_inv := 0, signal := omit, keypad := omit, more := 0, notify := 0, emergency := omit, imsi := \"\", lchan_type := 0, lchan_mode := 0, gcr := omit, sdp := \"v=0\\r\ o=Osmocom 0 0 IN IP4 1.1.1.1\\r\ s=GSM Call\\r\ c=IN IP4 1.2.3.4\\r\ t=0 0\\r\ m=audio 1234 RTP/AVP 0\\r\ a=rtpmap:0 GSM/8000\\r\ \" } } }"", new component reason: ""SIP_Tests.ttcn:300 : foo { msg_type := MNCC_SETUP_REQ (257), u := { signal := { callref := 5001, bearer_cap := omit, called := { number_type := GSM48_TON_UNKNOWN (0), plan := GSM48_NUMPLAN_E164 (1), presence := GSM48_PRES_IND_ALLOWED (0), screen := GSM48_SCR_IND_NOT_SCREENED (0), number := \"98766\" }, calling := { number_type := GSM48_TON_UNKNOWN (0), plan := GSM48_NUMPLAN_E164 (1), presence := GSM48_PRES_IND_ALLOWED (0), screen := GSM48_SCR_IND_NOT_SCREENED (0), number := \"12345\" }, redirecting := omit, connected := omit, cause := omit, progress := omit, useruser := omit, facility := omit, cccap := omit, ssversion := omit, clir_sup := 0, clir_inv := 0, signal := omit, keypad := omit, more := 0, notify := 0, emergency := omit, imsi := \"\", lchan_type := 0, lchan_mode := 0, gcr := omit, sdp := \"v=0\\r\ o=Osmocom 0 0 IN IP4 1.1.1.1\\r\ s=GSM Call\\r\ c=IN IP4 1.2.3.4\\r\ t=0 0\\r\ m=audio 1234 RTP/AVP 0\\r\ a=rtpmap:0 GSM/8000\\r\ \" } } }"" 16:28:12.217445 5 Misc_Helpers.ttcn:35 Stopping testcase execution from "SIP_Tests.ttcn":300 ``` output from log() looks nice and clean: ``` 16:28:12.217026 5 SIP_Tests.ttcn:299 FAIL: foo { msg_type := MNCC_SETUP_REQ (257), u := { signal := { callref := 5001, bearer_cap := omit, called := { number_type := GSM48_TON_UNKNOWN (0), plan := GSM48_NUMPLAN_E164 (1), presence := GSM48_PRES_IND_ALLOWED (0), screen := GSM48_SCR_IND_NOT_SCREENED (0), number := "98766" }, calling := { number_type := GSM48_TON_UNKNOWN (0), plan := GSM48_NUMPLAN_E164 (1), presence := GSM48_PRES_IND_ALLOWED (0), screen := GSM48_SCR_IND_NOT_SCREENED (0), number := "12345" }, redirecting := omit, connected := omit, cause := omit, progress := omit, useruser := omit, facility := omit, cccap := omit, ssversion := omit, clir_sup := 0, clir_inv := 0, signal := omit, keypad := omit, more := 0, notify := 0, emergency := omit, imsi := "", lchan_type := 0, lchan_mode := 0, gcr := omit, sdp := "v=0\r o=Osmocom 0 0 IN IP4 1.1.1.1\r s=GSM Call\r c=IN IP4 1.2.3.4\r t=0 0\r m=audio 1234 RTP/AVP 0\r a=rtpmap:0 GSM/8000\r " } } } ``` -- To view, visit https://gerrit.osmocom.org/c/osmo-ttcn3-hacks/+/34415?usp=email To unsubscribe, or for help writing mail filters, visit https://gerrit.osmocom.org/settings Gerrit-Project: osmo-ttcn3-hacks Gerrit-Branch: master Gerrit-Change-Id: Id48016657ebb83953fe74f65332f318edf8f75e6 Gerrit-Change-Number: 34415 Gerrit-PatchSet: 2 Gerrit-Owner: neels <nhofmeyr(a)sysmocom.de> Gerrit-Reviewer: Jenkins Builder Gerrit-Reviewer: laforge <laforge(a)osmocom.org> Gerrit-Reviewer: pespin <pespin(a)sysmocom.de> Gerrit-CC: fixeria <vyanitskiy(a)sysmocom.de> Gerrit-Attention: laforge <laforge(a)osmocom.org> Gerrit-Attention: fixeria <vyanitskiy(a)sysmocom.de> Gerrit-Attention: pespin <pespin(a)sysmocom.de> Gerrit-Comment-Date: Fri, 15 Sep 2023 14:48:49 +0000 Gerrit-HasComments: Yes Gerrit-Has-Labels: No Comment-In-Reply-To: neels <nhofmeyr(a)sysmocom.de> Comment-In-Reply-To: laforge <laforge(a)osmocom.org> Comment-In-Reply-To: fixeria <vyanitskiy(a)sysmocom.de> Comment-In-Reply-To: pespin <pespin(a)sysmocom.de> Gerrit-MessageType: comment