Check-in [cb680e9fde]
Overview
Comment:Added more input and output function error logging
Downloads: Tarball | ZIP archive | SQL archive
Timelines: family | ancestors | descendants | both | tls-1.8
Files: files | file ages | folders
SHA3-256: cb680e9fdec5d47805a5b8e96609002264e2ce6dad7b653f84ae4e8a5d131c40
User & Date: bohagan on 2024-06-07 02:38:03
Other Links: branch diff | manifest | tags
Context
2024-06-07
23:02
Test case fixes check-in: 0e844836ab user: bohagan tags: tls-1.8
02:38
Added more input and output function error logging check-in: cb680e9fde user: bohagan tags: tls-1.8
2024-06-06
13:54
Optimized checks for when to call Tls_WaitForConnect check-in: 9c66e07d09 user: bohagan tags: tls-1.8
Changes
257
258
259
260
261
262
263



264
265
266
267
268
269
270
	case SSL_ERROR_WANT_WRITE:
	case SSL_ERROR_WANT_X509_LOOKUP:
	case SSL_ERROR_WANT_CONNECT:
	case SSL_ERROR_WANT_ACCEPT:
	case SSL_ERROR_WANT_ASYNC:
	case SSL_ERROR_WANT_ASYNC_JOB:
	case SSL_ERROR_WANT_CLIENT_HELLO_CB:



	default:
	    /* The operation did not complete and should be retried later. */
	    dprintf("Operation did not complete, call function again later: %i", rc);
	    *errorCodePtr = EAGAIN;
	    dprintf("ERR(%d, %d) ", rc, *errorCodePtr);
	    Tls_Error(statePtr, "Operation did not complete, call function again later");
	    return -1;







>
>
>







257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
	case SSL_ERROR_WANT_WRITE:
	case SSL_ERROR_WANT_X509_LOOKUP:
	case SSL_ERROR_WANT_CONNECT:
	case SSL_ERROR_WANT_ACCEPT:
	case SSL_ERROR_WANT_ASYNC:
	case SSL_ERROR_WANT_ASYNC_JOB:
	case SSL_ERROR_WANT_CLIENT_HELLO_CB:
#if OPENSSL_VERSION_NUMBER >= 0x30000000L
	case SSL_ERROR_WANT_RETRY_VERIFY:
#endif
	default:
	    /* The operation did not complete and should be retried later. */
	    dprintf("Operation did not complete, call function again later: %i", rc);
	    *errorCodePtr = EAGAIN;
	    dprintf("ERR(%d, %d) ", rc, *errorCodePtr);
	    Tls_Error(statePtr, "Operation did not complete, call function again later");
	    return -1;
294
295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
310
 *    Reads input from the input device of the channel.
 *
 *-------------------------------------------------------------------
 */
static int TlsInputProc(ClientData instanceData, char *buf, int bufSize, int *errorCodePtr) {
    unsigned long backingError;
    State *statePtr = (State *) instanceData;
    int bytesRead;
    int err;

    *errorCodePtr = 0;

    dprintf("BIO_read(%d)", bufSize);

    /* Skip if user verify callback is still running */
    if (statePtr->flags & TLS_TCL_CALLBACK) {
	dprintf("Callback is running, reading 0 bytes");







|
<
<







297
298
299
300
301
302
303
304


305
306
307
308
309
310
311
 *    Reads input from the input device of the channel.
 *
 *-------------------------------------------------------------------
 */
static int TlsInputProc(ClientData instanceData, char *buf, int bufSize, int *errorCodePtr) {
    unsigned long backingError;
    State *statePtr = (State *) instanceData;
    int bytesRead, err;


    *errorCodePtr = 0;

    dprintf("BIO_read(%d)", bufSize);

    /* Skip if user verify callback is still running */
    if (statePtr->flags & TLS_TCL_CALLBACK) {
	dprintf("Callback is running, reading 0 bytes");
341
342
343
344
345
346
347

348
349
350
351
352
353
354
355
356
357




358



359


360




361

362
363
364

365
366
367
368
369
370
371
     *
     * Alternatively, we may want to handle the <0 return codes from
     * BIO_read specially (as advised in the RSA docs).  TLS's lower level BIO
     * functions play with the retry flags though, and this seems to work
     * correctly.  Similar fix in TlsOutputProc. - hobbs
     */
    ERR_clear_error();

    bytesRead = BIO_read(statePtr->bio, buf, bufSize);
    dprintf("BIO_read -> %d", bytesRead);

    err = SSL_get_error(statePtr->ssl, bytesRead);
    backingError = ERR_get_error();

#if 0
    if (bytesRead <= 0) {
	if (BIO_should_retry(statePtr->bio)) {
	    dprintf("I/O failed, will retry based on EAGAIN");




	    *errorCodePtr = EAGAIN;



	}


    }




#endif


    switch (err) {
	case SSL_ERROR_NONE:

	    dprintf("SSL_ERROR_NONE");
	    dprintBuffer(buf, bytesRead);
	    break;

	case SSL_ERROR_SSL:
	    /* A non-recoverable, fatal error in the SSL library occurred, usually a protocol error */
	    dprintf("SSL error, indicating that the connection has been aborted");







>






<


|
>
>
>
>
|
>
>
>

>
>
|
>
>
>
>
|
>



>







342
343
344
345
346
347
348
349
350
351
352
353
354
355

356
357
358
359
360
361
362
363
364
365
366
367
368
369
370
371
372
373
374
375
376
377
378
379
380
381
382
383
384
385
386
387
     *
     * Alternatively, we may want to handle the <0 return codes from
     * BIO_read specially (as advised in the RSA docs).  TLS's lower level BIO
     * functions play with the retry flags though, and this seems to work
     * correctly.  Similar fix in TlsOutputProc. - hobbs
     */
    ERR_clear_error();
    /* BIO_read, where 0 means EOF and -1 means error */
    bytesRead = BIO_read(statePtr->bio, buf, bufSize);
    dprintf("BIO_read -> %d", bytesRead);

    err = SSL_get_error(statePtr->ssl, bytesRead);
    backingError = ERR_get_error();


    if (bytesRead <= 0) {
	if (BIO_should_retry(statePtr->bio)) {
	    dprintf("Read failed with code=%d, bytes read=%d: should retry", err, bytesRead);
	    /* Some docs imply we should redo the BIO_read now */
	} else {
	    dprintf("Read failed with code=%d, bytes read=%d: error condition", err, bytesRead);
	}
	
	/* These are the same as BIO_retry_type */
	if (BIO_should_read(statePtr->bio)) {
	    dprintf("BIO has insufficient data to read and return");
	}
	if (BIO_should_write(statePtr->bio)) {
	    dprintf("BIO has pending data to write");
	}
	if (BIO_should_io_special(statePtr->bio)) {
	    int reason = BIO_get_retry_reason(statePtr->bio);
	    dprintf("BIO has some special condition other than read or write: code=%d", reason);
	}
	dprintf("BIO has pending data to write");
    }

    switch (err) {
	case SSL_ERROR_NONE:
	    /* I/O operation completed */
	    dprintf("SSL_ERROR_NONE");
	    dprintBuffer(buf, bytesRead);
	    break;

	case SSL_ERROR_SSL:
	    /* A non-recoverable, fatal error in the SSL library occurred, usually a protocol error */
	    dprintf("SSL error, indicating that the connection has been aborted");
387
388
389
390
391
392
393

394
395
396
397
398
















399
400
401
402
403
404
405
		bytesRead = 0;
		Tls_Error(statePtr, "EOF reached");
	    }
#endif
	    break;

	case SSL_ERROR_WANT_READ:

	    dprintf("Got SSL_ERROR_WANT_READ, mapping this to EAGAIN");
	    bytesRead = -1;
	    *errorCodePtr = EAGAIN;
	    Tls_Error(statePtr, "SSL_ERROR_WANT_READ");
	    break;

















	case SSL_ERROR_SYSCALL:
	    /* Some non-recoverable, fatal I/O error occurred */
	    dprintf("SSL_ERROR_SYSCALL");

	    if (backingError == 0 && bytesRead == 0) {
		/* Unexpected EOF from the peer for OpenSSL 1.1 */







>





>
>
>
>
>
>
>
>
>
>
>
>
>
>
>
>







403
404
405
406
407
408
409
410
411
412
413
414
415
416
417
418
419
420
421
422
423
424
425
426
427
428
429
430
431
432
433
434
435
436
437
438
		bytesRead = 0;
		Tls_Error(statePtr, "EOF reached");
	    }
#endif
	    break;

	case SSL_ERROR_WANT_READ:
	    /* Op did not complete due to not enough data was available. Retry later. */
	    dprintf("Got SSL_ERROR_WANT_READ, mapping this to EAGAIN");
	    bytesRead = -1;
	    *errorCodePtr = EAGAIN;
	    Tls_Error(statePtr, "SSL_ERROR_WANT_READ");
	    break;

	case SSL_ERROR_WANT_WRITE:
	    /* Op did not complete due to unable to sent all data to the BIO. Retry later. */
	    dprintf("Got SSL_ERROR_WANT_WRITE, mapping this to EAGAIN");
	    bytesRead = -1;
	    *errorCodePtr = EAGAIN;
	    Tls_Error(statePtr, "SSL_ERROR_WANT_WRITE");
	    break;

	case SSL_ERROR_WANT_X509_LOOKUP:
	    /* Op didn't complete since callback set by SSL_CTX_set_client_cert_cb() asked to be called again */
	    dprintf("Got SSL_ERROR_WANT_X509_LOOKUP, mapping it to EAGAIN");
	    *errorCodePtr = EAGAIN;
	    bytesRead = -1;
	    Tls_Error(statePtr, "SSL_ERROR_WANT_X509_LOOKUP");
	    break;

	case SSL_ERROR_SYSCALL:
	    /* Some non-recoverable, fatal I/O error occurred */
	    dprintf("SSL_ERROR_SYSCALL");

	    if (backingError == 0 && bytesRead == 0) {
		/* Unexpected EOF from the peer for OpenSSL 1.1 */
419
420
421
422
423
424
425

426
427
428
429
430








431
432
433
434
435
436
437
		*errorCodePtr = Tcl_GetErrno();
		bytesRead = -1;
		Tls_Error(statePtr, ERR_reason_error_string(backingError));
	    }
	    break;

	case SSL_ERROR_ZERO_RETURN:

	    dprintf("Got SSL_ERROR_ZERO_RETURN, this means an EOF has been reached");
	    bytesRead = 0;
	    *errorCodePtr = 0;
	    Tls_Error(statePtr, "Peer has closed the connection for writing by sending the close_notify alert");
	    break;









	default:
	    dprintf("Unknown error (err = %i), mapping to EOF", err);
	    *errorCodePtr = 0;
	    bytesRead = 0;
	    Tls_Error(statePtr, "Unknown error");
	    break;







>





>
>
>
>
>
>
>
>







452
453
454
455
456
457
458
459
460
461
462
463
464
465
466
467
468
469
470
471
472
473
474
475
476
477
478
479
		*errorCodePtr = Tcl_GetErrno();
		bytesRead = -1;
		Tls_Error(statePtr, ERR_reason_error_string(backingError));
	    }
	    break;

	case SSL_ERROR_ZERO_RETURN:
	    /* Peer has closed the connection for writing by sending the close_notify alert. No more data can be read. */
	    dprintf("Got SSL_ERROR_ZERO_RETURN, this means an EOF has been reached");
	    bytesRead = 0;
	    *errorCodePtr = 0;
	    Tls_Error(statePtr, "Peer has closed the connection for writing by sending the close_notify alert");
	    break;

	case SSL_ERROR_WANT_ASYNC:
	    /* Used with flag SSL_MODE_ASYNC, op didn't complete because an async engine is still processing data */
	    dprintf("Got SSL_ERROR_WANT_ASYNC, mapping this to EAGAIN");
	    bytesRead = -1;
	    *errorCodePtr = EAGAIN;
	    Tls_Error(statePtr, "SSL_ERROR_WANT_ASYNC");
	    break;

	default:
	    dprintf("Unknown error (err = %i), mapping to EOF", err);
	    *errorCodePtr = 0;
	    bytesRead = 0;
	    Tls_Error(statePtr, "Unknown error");
	    break;
458
459
460
461
462
463
464
465
466
467
468
469
470
471
472
 *
 *-------------------------------------------------------------------
 */
static int TlsOutputProc(ClientData instanceData, const char *buf, int toWrite, int *errorCodePtr) {
    unsigned long backingError;
    State *statePtr = (State *) instanceData;
    int written, err;

    *errorCodePtr = 0;

    dprintf("BIO_write(%p, %d)", (void *) statePtr, toWrite);
    dprintBuffer(buf, toWrite);

    /* Skip if user verify callback is still running */
    if (statePtr->flags & TLS_TCL_CALLBACK) {







<







500
501
502
503
504
505
506

507
508
509
510
511
512
513
 *
 *-------------------------------------------------------------------
 */
static int TlsOutputProc(ClientData instanceData, const char *buf, int toWrite, int *errorCodePtr) {
    unsigned long backingError;
    State *statePtr = (State *) instanceData;
    int written, err;

    *errorCodePtr = 0;

    dprintf("BIO_write(%p, %d)", (void *) statePtr, toWrite);
    dprintBuffer(buf, toWrite);

    /* Skip if user verify callback is still running */
    if (statePtr->flags & TLS_TCL_CALLBACK) {
524
525
526
527
528
529
530

531
532
533
534
535
536
























537
538

539
540
541
542
543
544
545
     *
     * Alternatively, we may want to handle the <0 return codes from
     * BIO_write specially (as advised in the RSA docs).  TLS's lower level
     * BIO functions play with the retry flags though, and this seems to
     * work correctly.  Similar fix in TlsInputProc. - hobbs
     */
    ERR_clear_error();

    written = BIO_write(statePtr->bio, buf, toWrite);
    dprintf("BIO_write(%p, %d) -> [%d]", (void *) statePtr, toWrite, written);

    err = SSL_get_error(statePtr->ssl, written);
    backingError = ERR_get_error();

























    switch (err) {
	case SSL_ERROR_NONE:

	    dprintf("SSL_ERROR_NONE");
	    if (written < 0) {
		written = 0;
	    }
	    break;

	case SSL_ERROR_SSL:







>






>
>
>
>
>
>
>
>
>
>
>
>
>
>
>
>
>
>
>
>
>
>
>
>


>







565
566
567
568
569
570
571
572
573
574
575
576
577
578
579
580
581
582
583
584
585
586
587
588
589
590
591
592
593
594
595
596
597
598
599
600
601
602
603
604
605
606
607
608
609
610
611
612
     *
     * Alternatively, we may want to handle the <0 return codes from
     * BIO_write specially (as advised in the RSA docs).  TLS's lower level
     * BIO functions play with the retry flags though, and this seems to
     * work correctly.  Similar fix in TlsInputProc. - hobbs
     */
    ERR_clear_error();
    /* SSL_write will return 1 for success or 0 for failure */
    written = BIO_write(statePtr->bio, buf, toWrite);
    dprintf("BIO_write(%p, %d) -> [%d]", (void *) statePtr, toWrite, written);

    err = SSL_get_error(statePtr->ssl, written);
    backingError = ERR_get_error();

    if (written <= 0) {
	if (BIO_should_retry(statePtr->bio)) {
	    dprintf("Write failed with code %d, bytes written=%d: should retry", err, written);
	} else {
	    dprintf("Write failed with code %d, bytes written=%d: error condition", err, written);
	}
	
	/* These are the same as BIO_retry_type */
	if (BIO_should_read(statePtr->bio)) {
	    dprintf("BIO has insufficient data to read and return");
	}
	if (BIO_should_write(statePtr->bio)) {
	    dprintf("BIO has pending data to write");
	}
	if (BIO_should_io_special(statePtr->bio)) {
	    int reason = BIO_get_retry_reason(statePtr->bio);
	    dprintf("BIO has some special condition other than read or write: code=%d", reason);
	}
	dprintf("BIO has pending data to write");

    } else {
	BIO_flush(statePtr->bio);
    }

    switch (err) {
	case SSL_ERROR_NONE:
	    /* I/O operation completed */
	    dprintf("SSL_ERROR_NONE");
	    if (written < 0) {
		written = 0;
	    }
	    break;

	case SSL_ERROR_SSL:
553
554
555
556
557
558
559

560


561
562
563
564

565
566
567
568
569
570
571



572
573
574
575
576
577
578
579
		Tls_Error(statePtr, "Unknown SSL error");
	    }
	    *errorCodePtr = ECONNABORTED;
	    written = -1;
	    break;

	case SSL_ERROR_WANT_READ:

	    dprintf(" write R BLOCK");


	    Tls_Error(statePtr, "SSL_ERROR_WANT_READ");
	    break;

	case SSL_ERROR_WANT_WRITE:

	    dprintf("Got SSL_ERROR_WANT_WRITE, mapping it to EAGAIN");
	    *errorCodePtr = EAGAIN;
	    written = -1;
	    Tls_Error(statePtr, "SSL_ERROR_WANT_WRITE");
	    break;

	case SSL_ERROR_WANT_X509_LOOKUP:



	    dprintf(" write X BLOCK");
	    Tls_Error(statePtr, "SSL_ERROR_WANT_X509_LOOKUP");
	    break;

	case SSL_ERROR_SYSCALL:
	    /* Some non-recoverable, fatal I/O error occurred */
	    dprintf("SSL_ERROR_SYSCALL");








>
|
>
>




>







>
>
>
|







620
621
622
623
624
625
626
627
628
629
630
631
632
633
634
635
636
637
638
639
640
641
642
643
644
645
646
647
648
649
650
651
652
653
		Tls_Error(statePtr, "Unknown SSL error");
	    }
	    *errorCodePtr = ECONNABORTED;
	    written = -1;
	    break;

	case SSL_ERROR_WANT_READ:
	    /* Op did not complete due to not enough data was available. Retry later. */
	    dprintf("Got SSL_ERROR_WANT_READ, mapping it to EAGAIN");
	    *errorCodePtr = EAGAIN;
	    written = -1;
	    Tls_Error(statePtr, "SSL_ERROR_WANT_READ");
	    break;

	case SSL_ERROR_WANT_WRITE:
	    /* Op did not complete due to unable to sent all data to the BIO. Retry later. */
	    dprintf("Got SSL_ERROR_WANT_WRITE, mapping it to EAGAIN");
	    *errorCodePtr = EAGAIN;
	    written = -1;
	    Tls_Error(statePtr, "SSL_ERROR_WANT_WRITE");
	    break;

	case SSL_ERROR_WANT_X509_LOOKUP:
	    /* Op didn't complete since callback set by SSL_CTX_set_client_cert_cb() asked to be called again */
	    dprintf("Got SSL_ERROR_WANT_X509_LOOKUP, mapping it to EAGAIN");
	    *errorCodePtr = EAGAIN;
	    written = -1;
	    Tls_Error(statePtr, "SSL_ERROR_WANT_X509_LOOKUP");
	    break;

	case SSL_ERROR_SYSCALL:
	    /* Some non-recoverable, fatal I/O error occurred */
	    dprintf("SSL_ERROR_SYSCALL");

594
595
596
597
598
599
600

601
602
603
604
605








606
607
608
609
610
611
612
		*errorCodePtr = Tcl_GetErrno();
		written = -1;
		Tls_Error(statePtr, ERR_reason_error_string(backingError));
	    }
	    break;

	case SSL_ERROR_ZERO_RETURN:

	    dprintf(" closed");
	    written = 0;
	    *errorCodePtr = 0;
	    Tls_Error(statePtr, "Peer has closed the connection for writing by sending the close_notify alert");
	    break;









	default:
	    dprintf("unknown error: %d", err);
	    Tls_Error(statePtr, "Unknown error");
	    break;
    }








>





>
>
>
>
>
>
>
>







668
669
670
671
672
673
674
675
676
677
678
679
680
681
682
683
684
685
686
687
688
689
690
691
692
693
694
695
		*errorCodePtr = Tcl_GetErrno();
		written = -1;
		Tls_Error(statePtr, ERR_reason_error_string(backingError));
	    }
	    break;

	case SSL_ERROR_ZERO_RETURN:
	    /* Peer has closed the connection for writing by sending the close_notify alert. No more data can be read. */
	    dprintf(" closed");
	    written = 0;
	    *errorCodePtr = 0;
	    Tls_Error(statePtr, "Peer has closed the connection for writing by sending the close_notify alert");
	    break;

	case SSL_ERROR_WANT_ASYNC:
	    /* Used with flag SSL_MODE_ASYNC, op didn't complete because an async engine is still processing data */
	    dprintf("Got SSL_ERROR_WANT_ASYNC, mapping this to EAGAIN");
	    *errorCodePtr = EAGAIN;
	    written = -1;
	    Tls_Error(statePtr, "SSL_ERROR_WANT_ASYNC");
	    break;

	default:
	    dprintf("unknown error: %d", err);
	    Tls_Error(statePtr, "Unknown error");
	    break;
    }

794
795
796
797
798
799
800

801
802
803
804
805
806
807
808
809
810
811
812
813
814
815
816
817
				 * TCL_READABLE, TCL_WRITABLE and TCL_EXCEPTION. */
{
    Tcl_Channel     downChan;
    State *statePtr = (State *) instanceData;
    Tcl_DriverWatchProc *watchProc;

    dprintf("TlsWatchProc(0x%x)", mask);


    /* Pretend to be dead as long as the verify callback is running.
     * Otherwise that callback could be invoked recursively. */
    if (statePtr->flags & TLS_TCL_CALLBACK) {
	dprintf("Callback is on-going, doing nothing");
	return;
    }

    dprintFlags(statePtr);

    downChan = Tls_GetParent(statePtr, TLS_TCL_FASTPATH);

    if (statePtr->flags & TLS_TCL_HANDSHAKE_FAILED) {
	dprintf("Asked to watch a socket with a failed handshake -- nothing can happen here");
	dprintf("Unregistering interest in the lower channel");

	watchProc = Tcl_ChannelWatchProc(Tcl_GetChannelType(downChan));







>








<
<







877
878
879
880
881
882
883
884
885
886
887
888
889
890
891
892


893
894
895
896
897
898
899
				 * TCL_READABLE, TCL_WRITABLE and TCL_EXCEPTION. */
{
    Tcl_Channel     downChan;
    State *statePtr = (State *) instanceData;
    Tcl_DriverWatchProc *watchProc;

    dprintf("TlsWatchProc(0x%x)", mask);
    dprintFlags(statePtr);

    /* Pretend to be dead as long as the verify callback is running.
     * Otherwise that callback could be invoked recursively. */
    if (statePtr->flags & TLS_TCL_CALLBACK) {
	dprintf("Callback is on-going, doing nothing");
	return;
    }



    downChan = Tls_GetParent(statePtr, TLS_TCL_FASTPATH);

    if (statePtr->flags & TLS_TCL_HANDSHAKE_FAILED) {
	dprintf("Asked to watch a socket with a failed handshake -- nothing can happen here");
	dprintf("Unregistering interest in the lower channel");

	watchProc = Tcl_ChannelWatchProc(Tcl_GetChannelType(downChan));