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_deff0... PS1, Line 195: og("FAIL: expected SIP message ", sip_expect); : setverdict(fail, "Received unexpected SIP message");

FYI, you can still do it like this: […]

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 " } } } ```