23:42:36.368511 - TTCN-3 Main Test Component started on ntaf. Version: CRL 113 200/6 R2A. 23:42:36.368637 - TTCN Logger v2.2 options: TimeStampFormat:=Time; LogEntityName:=No; LogEventTypes:=No; SourceInfoFormat:=Single; *.FileMask:=LOG_ALL | MATCHING; *.ConsoleMask:=ERROR | USER; LogFileSize:=0; LogFileNumber:=1; DiskFullAction:=Error 23:42:36.368930 - Connected to MC. 23:42:36.369583 - Executing control part of module HTTP2. 23:42:36.369623 HTTP2.ttcn:415 Execution of control part in module HTTP2 started. 23:42:36.369684 HTTP2.ttcn:289 Test case TC_http2 started. 23:42:36.369710 HTTP2.ttcn:289 Initializing variables, timers and ports of component type HTTP2.GeneralComp inside testcase TC_http2. 23:42:36.369787 HTTP2.ttcn:289 Port p was started. 23:42:36.369805 HTTP2.ttcn:289 Component type HTTP2.GeneralComp was initialized. 23:42:36.369819 HTTP2.ttcn:222 tsp_start: upgrade_conn (1) 23:42:36.369956 HTTP2.ttcn:224 Mapping port mtc:p to system:p. 23:42:36.370026 HTTP2.ttcn:224 Port p was mapped to system:p. 23:42:36.370091 HTTP2.ttcn:224 Map operation of mtc:p to system:p finished. 23:42:36.370129 HTTP2.ttcn:235 entering f__IPL4__PROVIDER__connect: :0 -> nghttp2.org:80 / TCP 23:42:36.800340 HTTP2.ttcn:238 connect result{ errorCode := omit, connId := 1, os_error_code := omit, os_error_text := omit } 23:42:36.800872 HTTP2.ttcn:252 Sent on p to system @IPL4asp_Types.ASP_Send : { connId := 1, proto := omit, msg := '474554202F6874747062696E2F697020485454502F312E310D0A436F6E6E656374696F6E3A20557067726164650D0A436F6E6E656374696F6E3A2048545450322D53657474696E67730D0A486F73743A206E6768747470322E6F72670D0A48545450322D53657474696E67733A2041414D414141426B414152414141414141414941414141410D0A557067726164653A206832630D0A557365722D4167656E743A20546974616E0D0A0D0A'O ("GET /httpbin/ip HTTP/1.1\r Connection: Upgrade\r Connection: HTTP2-Settings\r Host: nghttp2.org\r HTTP2-Settings: AAMAAABkAARAAAAAAAIAAAAA\r Upgrade: h2c\r User-Agent: Titan\r \r ") } 23:42:36.801002 HTTP2.ttcn:253 Start timer t: 5 s 23:42:37.086981 HTTP2.ttcn:255 Message enqueued on p from system @IPL4asp_Types.ASP_RecvFrom : { connId := 1, remName := "nghttp2.org", remPort := 80, locName := "192.168.139.129", locPort := 41696, proto := { tcp := { } }, userData := 0, msg := '485454502F312E312031303120537769746368696E672050726F746F636F6C730D0A436F6E6E656374696F6E3A20557067726164650D0A557067726164653A206832630D0A0D0A000012040000000000000300000064000400100000000100002000'O } id 1 23:42:37.087059 HTTP2.ttcn:257 Matching on port p succeeded: matched 23:42:37.087088 HTTP2.ttcn:257 Receive operation on port p succeeded, message from system(): @IPL4asp_Types.ASP_RecvFrom : { connId := 1, remName := "nghttp2.org", remPort := 80, locName := "192.168.139.129", locPort := 41696, proto := { tcp := { } }, userData := 0, msg := '485454502F312E312031303120537769746368696E672050726F746F636F6C730D0A436F6E6E656374696F6E3A20557067726164650D0A557067726164653A206832630D0A0D0A000012040000000000000300000064000400100000000100002000'O } id 1 23:42:37.087108 HTTP2.ttcn:257 Message with id 1 was extracted from the queue of p. 23:42:37.087272 HTTP2.ttcn:259 { msg := { start_line := { status_line := { version_major := 1, version_minor := 1, status_code := 101, reason_phrase := "Switching Protocols" } }, headers := { accept := omit, accept_charset := omit, accept_encoding := omit, accept_language := omit, accept_ranges := omit, age := omit, allow := omit, authorization := omit, cache_control := omit, connection := { { "Upgrade" } }, content_disposition := omit, content_encoding := omit, content_language := omit, content_length := omit, content_location := omit, content_range := omit, content_type := omit, cookie := omit, dasl := omit, dav := omit, date := omit, depth := omit, destination := omit, etag := omit, expect := omit, expires := omit, forwarded := omit, fRom := omit, host := omit, http2_settings := omit, iF := omit, if_match := omit, if_modified_since := omit, if_none_match := omit, if_range := omit, if_schedule_tag_match := omit, if_unmodified_since := omit, last_modified := omit, location := omit, lock_token := omit, max_forwards := omit, mime_version := omit, ordering_type := omit, origin := omit, overwrite := omit, position := omit, pragma := omit, prefer := omit, preference_applied := omit, proxy_authenticate := omit, proxy_authorization := omit, range := omit, referer := omit, retry_after := omit, schedule_reply := omit, schedule_tag := omit, sec_websocket_accept := omit, sec_websocket_extensions := omit, sec_websocket_key := omit, sec_websocket_protocol := omit, sec_websocket_version := omit, server := omit, set_cookie := omit, slug := omit, strict_transport_security := omit, tE := omit, tImeout := omit, trailer := omit, transfer_encoding := omit, upgrade := { { "h2c" } }, user_agent := omit, vary := omit, via := omit, www_authenticate := omit, warning := omit, undefined_header_list := omit }, body := '000012040000000000000300000064000400100000000100002000'O } } 23:42:37.087534 HTTP2.ttcn:299 Sent on p to system @IPL4asp_Types.ASP_Send : { connId := 1, proto := omit, msg := '505249202A20485454502F322E300D0A0D0A534D0D0A0D0A'O ("PRI * HTTP/2.0\r \r SM\r \r ") } 23:42:37.087657 HTTP2.ttcn:301 Sent on p to system @IPL4asp_Types.ASP_Send : { connId := 1, proto := omit, msg := '000012040000000000000200000000000300000064000440000000'O } 23:42:37.087702 HTTP2.ttcn:303 Sent on p to system @IPL4asp_Types.ASP_Send : { connId := 1, proto := omit, msg := '0000040800000000003FFF0001'O } 23:42:37.087729 HTTP2.ttcn:313 Warning: Re-starting timer t, which is already active (running or expired). 23:42:37.087744 HTTP2.ttcn:313 Start timer t: 1 s 23:42:37.088552 HTTP2.ttcn:315 Message enqueued on p from system @IPL4asp_Types.ASP_RecvFrom : { connId := 1, remName := "nghttp2.org", remPort := 80, locName := "192.168.139.129", locPort := 41696, proto := { tcp := { } }, userData := 0, msg := '0000BC010400000001886196D07ABE9403EA6A22541002EA8072E342B8CBEA62D1BF5F8B1D75D0620D263D4C7441EA0F0D02333154012A409619085421621EA4D87A161D141FC2C4B0B216A4987423834D9697408FF2B4632752D522D3947216C5AC4A7F8602E0005F65CF7686AA69D29AFCFF7C880AE152A9A74A6BF3408BF2B4B60E92AC7AD263D48F89DD0E8C1AB6E4C5934F408CF2B794216AEC3A4A4498F57F8A0FDA949E42C11D07275F4090F2B10F524B52564FAACAB1EB498F523F85A8E8A8D2CB'O } id 2 23:42:37.088608 HTTP2.ttcn:315 Message enqueued on p from system @IPL4asp_Types.ASP_RecvFrom : { connId := 1, remName := "nghttp2.org", remPort := 80, locName := "192.168.139.129", locPort := 41696, proto := { tcp := { } }, userData := 0, msg := '00001F0001000000017B0A2020226F726967696E223A202239312E38322E3130302E3539220A7D0A'O } id 3 23:42:37.088722 HTTP2.ttcn:317 Matching on port p .msg := '0000BC010400000001886196D07ABE9403EA6A22541002EA8072E342B8CBEA62D1BF5F8B1D75D0620D263D4C7441EA0F0D02333154012A409619085421621EA4D87A161D141FC2C4B0B216A4987423834D9697408FF2B4632752D522D3947216C5AC4A7F8602E0005F65CF7686AA69D29AFCFF7C880AE152A9A74A6BF3408BF2B4B60E92AC7AD263D48F89DD0E8C1AB6E4C5934F408CF2B794216AEC3A4A4498F57F8A0FDA949E42C11D07275F4090F2B10F524B52564FAACAB1EB498F523F85A8E8A8D2CB'O with decmatch HTTP2_Frame: { settings_frame := { ack_flag := true, settings := omit } } unmatched: First message in the queue does not match the template: 23:42:37.088803 HTTP2.ttcn:328 Matching on port p .msg := '0000BC010400000001886196D07ABE9403EA6A22541002EA8072E342B8CBEA62D1BF5F8B1D75D0620D263D4C7441EA0F0D02333154012A409619085421621EA4D87A161D141FC2C4B0B216A4987423834D9697408FF2B4632752D522D3947216C5AC4A7F8602E0005F65CF7686AA69D29AFCFF7C880AE152A9A74A6BF3408BF2B4B60E92AC7AD263D48F89DD0E8C1AB6E4C5934F408CF2B794216AEC3A4A4498F57F8A0FDA949E42C11D07275F4090F2B10F524B52564FAACAB1EB498F523F85A8E8A8D2CB'O with decmatch HTTP2_Frame: { settings_frame := { ack_flag := false, settings := * } } unmatched: First message in the queue does not match the template: 23:42:37.088880 HTTP2.ttcn:342 Matching on port p .msg := '0000BC010400000001886196D07ABE9403EA6A22541002EA8072E342B8CBEA62D1BF5F8B1D75D0620D263D4C7441EA0F0D02333154012A409619085421621EA4D87A161D141FC2C4B0B216A4987423834D9697408FF2B4632752D522D3947216C5AC4A7F8602E0005F65CF7686AA69D29AFCFF7C880AE152A9A74A6BF3408BF2B4B60E92AC7AD263D48F89DD0E8C1AB6E4C5934F408CF2B794216AEC3A4A4498F57F8A0FDA949E42C11D07275F4090F2B10F524B52564FAACAB1EB498F523F85A8E8A8D2CB'O with decmatch HTTP2_Frame: { header_frame := { stream_id := 1, end_stream_flag := true, end_header_flag := true, priority_data := omit, header_block_fragment := ?, padding := omit } } unmatched: First message in the queue does not match the template: 23:42:37.088961 HTTP2.ttcn:362 Matching on port p .msg := '0000BC010400000001886196D07ABE9403EA6A22541002EA8072E342B8CBEA62D1BF5F8B1D75D0620D263D4C7441EA0F0D02333154012A409619085421621EA4D87A161D141FC2C4B0B216A4987423834D9697408FF2B4632752D522D3947216C5AC4A7F8602E0005F65CF7686AA69D29AFCFF7C880AE152A9A74A6BF3408BF2B4B60E92AC7AD263D48F89DD0E8C1AB6E4C5934F408CF2B794216AEC3A4A4498F57F8A0FDA949E42C11D07275F4090F2B10F524B52564FAACAB1EB498F523F85A8E8A8D2CB'O with decmatch HTTP2_Frame: { data_frame := { stream_id := 1, end_stream_flag := ?, data := ?, padding := omit } } unmatched: First message in the queue does not match the template: 23:42:37.089027 HTTP2.ttcn:373 Matching on port p .msg := '0000BC010400000001886196D07ABE9403EA6A22541002EA8072E342B8CBEA62D1BF5F8B1D75D0620D263D4C7441EA0F0D02333154012A409619085421621EA4D87A161D141FC2C4B0B216A4987423834D9697408FF2B4632752D522D3947216C5AC4A7F8602E0005F65CF7686AA69D29AFCFF7C880AE152A9A74A6BF3408BF2B4B60E92AC7AD263D48F89DD0E8C1AB6E4C5934F408CF2B794216AEC3A4A4498F57F8A0FDA949E42C11D07275F4090F2B10F524B52564FAACAB1EB498F523F85A8E8A8D2CB'O with decmatch HTTP2_Frame: { ping_frame := ? } unmatched: First message in the queue does not match the template: 23:42:37.089058 HTTP2.ttcn:386 Matching on port p succeeded: matched 23:42:37.089085 HTTP2.ttcn:386 Receive operation on port p succeeded, message from system(): @IPL4asp_Types.ASP_RecvFrom : { connId := 1, remName := "nghttp2.org", remPort := 80, locName := "192.168.139.129", locPort := 41696, proto := { tcp := { } }, userData := 0, msg := '0000BC010400000001886196D07ABE9403EA6A22541002EA8072E342B8CBEA62D1BF5F8B1D75D0620D263D4C7441EA0F0D02333154012A409619085421621EA4D87A161D141FC2C4B0B216A4987423834D9697408FF2B4632752D522D3947216C5AC4A7F8602E0005F65CF7686AA69D29AFCFF7C880AE152A9A74A6BF3408BF2B4B60E92AC7AD263D48F89DD0E8C1AB6E4C5934F408CF2B794216AEC3A4A4498F57F8A0FDA949E42C11D07275F4090F2B10F524B52564FAACAB1EB498F523F85A8E8A8D2CB'O } id 2 23:42:37.089105 HTTP2.ttcn:386 Message with id 2 was extracted from the queue of p. 23:42:37.089118 HTTP2.ttcn:395 received something :{ header_frame := { stream_id := 1, end_stream_flag := false, end_header_flag := true, priority_data := omit, header_block_fragment := '886196D07ABE9403EA6A22541002EA8072E342B8CBEA62D1BF5F8B1D75D0620D263D4C7441EA0F0D02333154012A409619085421621EA4D87A161D141FC2C4B0B216A4987423834D9697408FF2B4632752D522D3947216C5AC4A7F8602E0005F65CF7686AA69D29AFCFF7C880AE152A9A74A6BF3408BF2B4B60E92AC7AD263D48F89DD0E8C1AB6E4C5934F408CF2B794216AEC3A4A4498F57F8A0FDA949E42C11D07275F4090F2B10F524B52564FAACAB1EB498F523F85A8E8A8D2CB'O, padding := omit } } 23:42:37.089695 HTTP2.ttcn:317 Matching on port p .msg := '00001F0001000000017B0A2020226F726967696E223A202239312E38322E3130302E3539220A7D0A'O with decmatch HTTP2_Frame: { settings_frame := { ack_flag := true, settings := omit } } unmatched: First message in the queue does not match the template: 23:42:37.089742 HTTP2.ttcn:328 Matching on port p .msg := '00001F0001000000017B0A2020226F726967696E223A202239312E38322E3130302E3539220A7D0A'O with decmatch HTTP2_Frame: { settings_frame := { ack_flag := false, settings := * } } unmatched: First message in the queue does not match the template: 23:42:37.089784 HTTP2.ttcn:342 Matching on port p .msg := '00001F0001000000017B0A2020226F726967696E223A202239312E38322E3130302E3539220A7D0A'O with decmatch HTTP2_Frame: { header_frame := { stream_id := 1, end_stream_flag := true, end_header_flag := true, priority_data := omit, header_block_fragment := ?, padding := omit } } unmatched: First message in the queue does not match the template: 23:42:37.089819 HTTP2.ttcn:362 Matching on port p succeeded: matched 23:42:37.089841 HTTP2.ttcn:362 Receive operation on port p succeeded, message from system(): @IPL4asp_Types.ASP_RecvFrom : { connId := 1, remName := "nghttp2.org", remPort := 80, locName := "192.168.139.129", locPort := 41696, proto := { tcp := { } }, userData := 0, msg := '00001F0001000000017B0A2020226F726967696E223A202239312E38322E3130302E3539220A7D0A'O } id 3 23:42:37.089864 HTTP2.ttcn:362 Message with id 3 was extracted from the queue of p. 23:42:37.089879 HTTP2.ttcn:371 received data_frame :{ data_frame := { stream_id := 1, end_stream_flag := true, data := '7B0A2020226F726967696E223A202239312E38322E3130302E3539220A7D0A'O ("{ \"origin\": \"91.82.100.59\" } "), padding := omit } } 23:42:37.370043 HTTP2.ttcn:315 Message enqueued on p from system @IPL4asp_Types.ASP_RecvFrom : { connId := 1, remName := "nghttp2.org", remPort := 80, locName := "192.168.139.129", locPort := 41696, proto := { tcp := { } }, userData := 0, msg := '000000040100000000'O } id 4 23:42:37.370146 HTTP2.ttcn:317 Matching on port p succeeded: matched 23:42:37.370174 HTTP2.ttcn:317 Receive operation on port p succeeded, message from system(): @IPL4asp_Types.ASP_RecvFrom : { connId := 1, remName := "nghttp2.org", remPort := 80, locName := "192.168.139.129", locPort := 41696, proto := { tcp := { } }, userData := 0, msg := '000000040100000000'O } id 4 23:42:37.370192 HTTP2.ttcn:317 Message with id 4 was extracted from the queue of p. 23:42:37.370234 HTTP2.ttcn:326 received init_settings_frame_ack :{ settings_frame := { ack_flag := true, settings := omit } } 23:42:38.088409 HTTP2.ttcn:398 Timeout t: 1 s 23:42:38.088488 HTTP2.ttcn:398 Bye 23:42:38.088556 HTTP2.ttcn:281 p: f__IPL4__close: proto { unspecified := { } } connId 1 23:42:38.088928 HTTP2.ttcn:282 close result{ errorCode := omit, connId := 1, os_error_code := omit, os_error_text := omit } 23:42:38.088994 HTTP2.ttcn:283 Unmapping port mtc:p from system:p. 23:42:38.089348 HTTP2.ttcn:283 Port p was unmapped from system:p. 23:42:38.089417 HTTP2.ttcn:283 Unmap operation of mtc:p from system:p finished. 23:42:38.089442 HTTP2.ttcn:410 setverdict(pass): none -> pass 23:42:38.089458 HTTP2.ttcn:410 Terminating component type HTTP2.GeneralComp. 23:42:38.089474 HTTP2.ttcn:410 Port p was stopped. 23:42:38.089488 HTTP2.ttcn:410 Component type HTTP2.GeneralComp was shut down inside testcase TC_http2. 23:42:38.089500 HTTP2.ttcn:410 Waiting for PTCs to finish. 23:42:38.089548 HTTP2.ttcn:410 Setting final verdict of the test case. 23:42:38.089567 HTTP2.ttcn:410 Local verdict of MTC: pass 23:42:38.089581 HTTP2.ttcn:410 No PTCs were created. 23:42:38.089592 HTTP2.ttcn:410 Test case TC_http2 finished. Verdict: pass 23:42:38.089608 HTTP2.ttcn:416 Execution of control part in module HTTP2 finished. 23:42:38.089972 - Verdict statistics: 0 none (0.00 %), 1 pass (100.00 %), 0 inconc (0.00 %), 0 fail (0.00 %), 0 error (0.00 %). 23:42:38.090006 - Test execution summary: 1 test case was executed. Overall verdict: pass 23:42:38.090016 - Exit was requested from MC. Terminating MTC.