Curious on why QUIC works on 3.2 but not 3.3 in PUT on NonStop

[rsbeckerca]

Is there some fundamental difference in how QUIC is implemented between 3.2 and 3.3? I have 70-test_quic_lcidm.t failing pretty broadly on timeouts. I'm not willing to say this a bug at this point but would raise one if it turns out to be.

Basically the test runs and then fails starting here (in 3.3 across pretty much all commits):

        # INFO:  @ /home/jenkinsbuild/.jenkins/workspace/OpenSSL-3.3_Monitor/test/quic_multistream_test.c:5833
        # Running script 11 (order=0, blocking=0)
        # ERROR: (int) 'SSL_get_error(c_tgt, 0) == SSL_ERROR_ZERO_RETURN' failed @ /home/jenkinsbuild/.jenkins/workspace/OpenSSL-3.3_Monitor/test/quic_multistream_test.c:1439
        # [1] compared to [6]
        # ERROR:  @ /home/jenkinsbuild/.jenkins/workspace/OpenSSL-3.3_Monitor/test/quic_multistream_test.c:2010
        # failed in script "script 11" at op 3, thread 0
        # 
        # 
00000001000BFC20000D000400000000:error:0A0000CF:SSL routines:quic_read:protocol is shutdown:/home/jenkinsbuild/.jenkins/workspace/OpenSSL-3.3_Monitor/ssl/quic/quic_impl.c:2756:
        # INFO:  @ /home/jenkinsbuild/.jenkins/workspace/OpenSSL-3.3_Monitor/test/quic_multistream_test.c:2042
        # client side is closed: 18446744073709551615(?)/0(PADDING), local, transport, reason: "-"
        # ERROR: (int) 'ossl_time_compare(ossl_time_now(), op_deadline) <= 0' failed @ /home/jenkinsbuild/.jenkins/workspace/OpenSSL-3.3_Monitor/test/quic_multistream_test.c:1083
        # [1] compared to [0]
        # ERROR:  @ /home/jenkinsbuild/.jenkins/workspace/OpenSSL-3.3_Monitor/test/quic_multistream_test.c:1084
        # op 1 timed out on thread 1

[Sashan]

The code for test 11 reads as follows:

2375 /* 11. Many threads accepted on the same client connection */
2376 static const struct script_op script_11_child[] = {
2377     OP_C_ACCEPT_STREAM_WAIT (a)
2378     OP_C_READ_EXPECT        (a, "foo", 3)
2379     OP_C_EXPECT_FIN         (a)
2380
2381     OP_END
2382 };
2383
2384 static const struct script_op script_11[] = {
2385     OP_C_SET_ALPN           ("ossltest")
2386     OP_C_CONNECT_WAIT       ()
2387     OP_C_SET_DEFAULT_STREAM_MODE(SSL_DEFAULT_STREAM_MODE_NONE)
2388
2389     OP_NEW_THREAD           (5, script_11_child)
2390
2391     OP_S_NEW_STREAM_BIDI    (a, ANY_ID)
2392     OP_S_WRITE              (a, "foo", 3)
2393     OP_S_CONCLUDE           (a)
2394
2395     OP_S_NEW_STREAM_BIDI    (b, ANY_ID)
2396     OP_S_WRITE              (b, "foo", 3)
2397     OP_S_CONCLUDE           (b)
2398
2399     OP_S_NEW_STREAM_BIDI    (c, ANY_ID)
2400     OP_S_WRITE              (c, "foo", 3)
2401     OP_S_CONCLUDE           (c)
2402
2403     OP_S_NEW_STREAM_BIDI    (d, ANY_ID)
2404     OP_S_WRITE              (d, "foo", 3)
2405     OP_S_CONCLUDE           (d)
2406
2407     OP_S_NEW_STREAM_BIDI    (e, ANY_ID)
2408     OP_S_WRITE              (e, "foo", 3)
2409     OP_S_CONCLUDE           (e)
2410
2411     OP_END
2412 };

If I understand things right the test idea is as follows: create 5 server threads (script_11_child1) which accept stream from client thread (script_11). The client creates 5 streams and sends word foo` over each stream. The error report:

failed in script "script 11" at op 3, thread 0

I suspect the error must be coming from child 0 script_11_child, because main thread id should be -1 (if I understand the code correctly). the op 3 indicates we must be failing at line 2379 OP_C_EXPECT_FIN (a) I'm not able to trigger the bug on *BSD or linux.

quic_read:protocol is shutdown error indicates a failure in quic_read(). It looks like the quick connection is in shutting_down state already when test probes the state by code here (at line 1429):

1423         case OPK_C_EXPECT_FIN:
1424             {
1425                 char buf[1];
1426                 size_t bytes_read = 0;
1427                 int r;
1428
1429                 r = SSL_read_ex(c_tgt, buf, sizeof(buf), &bytes_read);
1430                 if (!check_consistent_want(c_tgt, r)
1431                     || !TEST_false(r)
1432                     || !TEST_size_t_eq(bytes_read, 0))
1433                     goto out;
1434
1435                 if (is_want(c_tgt, 0))
1436                     C_SPIN_AGAIN();
1437
1438                 if (!TEST_int_eq(SSL_get_error(c_tgt, 0),
1439                                  SSL_ERROR_ZERO_RETURN))
1440                     goto out;
1441
1442                 if (!TEST_int_eq(SSL_want(c_tgt), SSL_NOTHING))
1443                     goto out;
1444             }
1445             break;

I need to check history of this test and related area to better understand why it is seen on 3.3 on not in 3.2.

[nhorman]

That shouldn't be referring to a FIN-WAIT socket in the sense of the socket api (as QUIC is entirely UDP based). here FIN refers to the quic stream state (see section 3.1 of https://datatracker.ietf.org/doc/html/rfc9000 for some details)

If I had to take an initial guess, i would venture that the client thread didn't yield properly and give the server the opportunity to send a FIN frame, leading to the client not getting the ZERO_RETURN error it was expecting

[rsbeckerca]

@nhorman My bad on the FIN-WAIT, but it is entirely plausible that a yield was not happening to allow the packet through. Any suggestion on where the yield should go? I can try that.

[nhorman]

well, I don't think an express sleep is the right final answer, but in the client script, you might just insert a OP_SLEEP command prior to the command to check for a FIN frame

[rsbeckerca]

We could do a pthread_yield() in the code perhaps.

[rsbeckerca]

Trying the OP_SLEEP. Will report back.

[rsbeckerca]

Fantastic! That did it. I'm going to put this into a fix for 3.3 and 3.4 - also should go to 3.2, which I think is only coincidentally working.

[rsbeckerca]

Converted to an issue and pull request. Thanks @nhorman and @Sashan.

[Sashan]

thanks for the quick turnaround here. I agree with the analysis by @nhorman. The test seems to appear in 3.3 for the first time when support for multistream clients has been introduced. Putting all bits together this is what happens:

• server thread fails at operation 3 because it fails to detect stream termination initiated by server thread
• the error is handled then by main thread which orchestrates the test. the code in main thread queries the stream state here at line 2023:

2002 out:                                                                                                                                                                                                                                                                                                                   
2003     s_unlock(h, hl); /* idempotent */                                                                                                                                                                                                                                                                                  
2004     if (!testresult) {                                                                                                                                                                                                                                                                                                 
2005         size_t i;                                                                                                                                                                                                                                                                                                      
2006         const QUIC_TERMINATE_CAUSE *tcause;                                                                                                                                                                                                                                                                            
2007         const char *e_str, *f_str;                                                                                                                                                                                                                                                                                     
2008                                                                                                                                                                                                                                                                                                                        
....
2020         if (h->c_conn != NULL) {                                                                                                                                                                                                                                                                                       
2021             SSL_CONN_CLOSE_INFO cc_info = {0};                                                                                                                                                                                                                                                                         
2022                                                                                                                                                                                                                                                                                                                        
2023             if (SSL_get_conn_close_info(h->c_conn, &cc_info, sizeof(cc_info))) {                                                                                                                                                                                                                                       
2024                 e_str = ossl_quic_err_to_string(cc_info.error_code);                                                                                                                                                                                                                                                   
2025                 f_str = ossl_quic_frame_type_to_string(cc_info.frame_type);                                                                                                                                                                                                                                            
2026                                                                                                                                                                                                                                                                                                                        
2027                 if (e_str == NULL)                                                                                                                                                                                                                                                                                     
2028                     e_str = "?";                                                                                                                                                                                                                                                                                       
2029                 if (f_str == NULL)                                                                                                                                                                                                                                                                                     
2030                     f_str = "?";                                                                                                                                                                                                                                                                                       
2031                                                                                                                                                                                                                                                                                                                        
2032                 TEST_info("client side is closed: %llu(%s)/%llu(%s), "                                                                                                                                                                                                                                                 
2033                           "%s, %s, reason: \"%s\"",                                                                                                                                                                                                                                                                    
2034                           (unsigned long long)cc_info.error_code,                                                                                                                                                                                                                                                      
2035                           e_str,                                                                                                                                                                                                                                                                                       
2036                           (unsigned long long)cc_info.frame_type,                                                                                                                                                                                                                                                      
2037                           f_str,                                                                                                                                                                                                                                                                                       
2038                           (cc_info.flags & SSL_CONN_CLOSE_FLAG_LOCAL) != 0                                                                                                                                                                                                                                             
2039                             ? "local" : "remote",                                                                                                                                                                                                                                                                      
2040                           (cc_info.flags & SSL_CONN_CLOSE_FLAG_TRANSPORT) != 0                                                                                                                                                                                                                                         
2041                             ? "transport" : "app",                                                                                                                                                                                                                                                                     
2042                           cc_info.reason != NULL ? cc_info.reason : "-");                                                                                                                                                                                                                                              

However when we execute line 2023 the stream is gone already.