У меня в поле есть устройство, подключающееся к моей службе по протоколу SSL с использованием stunnel. Хороший новый действующий сертификат ... все остальные устройства работают нормально. Но этот, по некоторым причинам, терпит неудачу при первой попытке соединиться. Затем, если у меня включено кэширование сеанса, оно будет работать нормально при последующих попытках. Вот журнал отладки от Stunnel. Любые идеи о том, что я мог бы изменить, чтобы заставить это работать в первый раз ??
Вот первое соединение:
2020.05.01 13:55:58 LOG7[12830:140495407708160]: Clients allowed=500
2020.05.01 13:55:58 LOG5[12830:140495407708160]: stunnel 4.56 on x86_64-redhat-linux-gnu platform
2020.05.01 13:55:58 LOG5[12830:140495407708160]: Compiled/running with OpenSSL 1.0.2k-fips 26 Jan 2017
2020.05.01 13:55:58 LOG5[12830:140495407708160]: Threading:PTHREAD Sockets:POLL,IPv6 SSL:ENGINE,OCSP,FIPS Auth:LIBWRAP
2020.05.01 13:55:58 LOG5[12830:140495407708160]: Reading configuration from file test2.conf
2020.05.01 13:55:58 LOG5[12830:140495407708160]: FIPS mode is disabled
2020.05.01 13:55:58 LOG7[12830:140495407708160]: Compression not enabled
2020.05.01 13:55:58 LOG7[12830:140495407708160]: PRNG seeded successfully
2020.05.01 13:55:58 LOG6[12830:140495407708160]: Initializing service [60666-v570]
2020.05.01 13:55:58 LOG7[12830:140495407708160]: Certificate: [redacted]
2020.05.01 13:55:58 LOG7[12830:140495407708160]: Certificate loaded
2020.05.01 13:55:58 LOG7[12830:140495407708160]: Key file: [redacted]
2020.05.01 13:55:58 LOG7[12830:140495407708160]: Private key loaded
2020.05.01 13:55:58 LOG7[12830:140495407708160]: Could not load DH parameters from [redacted]
2020.05.01 13:55:58 LOG7[12830:140495407708160]: Using hardcoded DH parameters
2020.05.01 13:55:58 LOG7[12830:140495407708160]: DH initialized with 2048-bit key
2020.05.01 13:55:58 LOG7[12830:140495407708160]: ECDH initialized with curve prime256v1
2020.05.01 13:55:58 LOG7[12830:140495407708160]: SSL options set: 0x03000004
2020.05.01 13:55:58 LOG5[12830:140495407708160]: Configuration successful
2020.05.01 13:55:58 LOG7[12830:140495407708160]: Service [60666-v570] (FD=12) bound to 0.0.0.0:60666
2020.05.01 13:55:58 LOG7[12830:140495407708160]: Created pid file /var/run/stunnel.pid
2020.05.01 13:56:35 LOG7[12830:140495407708160]: Service [60666-v570] accepted (FD=3) from [redacted]
2020.05.01 13:56:35 LOG7[12830:140495407703808]: Service [60666-v570] started
2020.05.01 13:56:35 LOG7[12830:140495407703808]: Waiting for a libwrap process
2020.05.01 13:56:35 LOG7[12830:140495407703808]: Acquired libwrap process #0
2020.05.01 13:56:35 LOG7[12830:140495407703808]: Releasing libwrap process #0
2020.05.01 13:56:35 LOG7[12830:140495407703808]: Released libwrap process #0
2020.05.01 13:56:35 LOG7[12830:140495407703808]: Service [60666-v570] permitted by libwrap from [redacted]
2020.05.01 13:56:35 LOG5[12830:140495407703808]: Service [60666-v570] accepted connection from [redacted]
2020.05.01 13:56:35 LOG7[12830:140495407703808]: SSL state (accept): before/accept initialization
2020.05.01 13:56:35 LOG7[12830:140495407703808]: SNI: no virtual services defined
2020.05.01 13:56:35 LOG7[12830:140495407703808]: SSL state (accept): SSLv3 read client hello A
2020.05.01 13:56:35 LOG7[12830:140495407703808]: SSL state (accept): SSLv3 write server hello A
2020.05.01 13:56:35 LOG7[12830:140495407703808]: SSL state (accept): SSLv3 write certificate A
2020.05.01 13:56:35 LOG7[12830:140495407703808]: SSL state (accept): SSLv3 write server done A
2020.05.01 13:56:35 LOG7[12830:140495407703808]: SSL state (accept): SSLv3 flush data
2020.05.01 13:56:35 LOG7[12830:140495407703808]: SSL state (accept): SSLv3 read client certificate A
Клиент сдается в этот момент ... через 32 секунды. ..но мой сервер stunnel завершает процесс подключения.
2020.05.01 13:57:07 LOG7[12830:140495407703808]: SSL state (accept): SSLv3 read client key exchange A
2020.05.01 13:57:07 LOG7[12830:140495407703808]: SSL state (accept): SSLv3 read certificate verify A
2020.05.01 13:57:07 LOG7[12830:140495407703808]: SSL state (accept): SSLv3 read finished A
2020.05.01 13:57:07 LOG7[12830:140495407703808]: SSL state (accept): SSLv3 write change cipher spec A
2020.05.01 13:57:07 LOG7[12830:140495407703808]: SSL state (accept): SSLv3 write finished A
2020.05.01 13:57:07 LOG7[12830:140495407703808]: SSL state (accept): SSLv3 flush data
2020.05.01 13:57:07 LOG7[12830:140495407703808]: 1 items in the session cache
2020.05.01 13:57:07 LOG7[12830:140495407703808]: 0 client connects (SSL_connect())
2020.05.01 13:57:07 LOG7[12830:140495407703808]: 0 client connects that finished
2020.05.01 13:57:07 LOG7[12830:140495407703808]: 0 client renegotiations requested
2020.05.01 13:57:07 LOG7[12830:140495407703808]: 1 server connects (SSL_accept())
2020.05.01 13:57:07 LOG7[12830:140495407703808]: 1 server connects that finished
2020.05.01 13:57:07 LOG7[12830:140495407703808]: 0 server renegotiations requested
2020.05.01 13:57:07 LOG7[12830:140495407703808]: 0 session cache hits
2020.05.01 13:57:07 LOG7[12830:140495407703808]: 0 external session cache hits
2020.05.01 13:57:07 LOG7[12830:140495407703808]: 0 session cache misses
2020.05.01 13:57:07 LOG7[12830:140495407703808]: 0 session cache timeouts
2020.05.01 13:57:07 LOG6[12830:140495407703808]: SSL accepted: new session negotiated
2020.05.01 13:57:07 LOG6[12830:140495407703808]: Negotiated TLSv1/SSLv3 ciphersuite: AES256-SHA (256-bit encryption)
2020.05.01 13:57:07 LOG6[12830:140495407703808]: Compression: null, expansion: null
2020.05.01 13:57:07 LOG6[12830:140495407703808]: local_bind succeeded on an ephemeral port
2020.05.01 13:57:07 LOG6[12830:140495407703808]: connect_blocking: connecting 127.0.0.1:50001
2020.05.01 13:57:07 LOG7[12830:140495407703808]: connect_blocking: s_poll_wait 127.0.0.1:50001: waiting 10 seconds
2020.05.01 13:57:07 LOG5[12830:140495407703808]: connect_blocking: connected 127.0.0.1:50001
2020.05.01 13:57:07 LOG5[12830:140495407703808]: Service [60666-v570] connected remote server from 127.0.0.66:43790
2020.05.01 13:57:07 LOG7[12830:140495407703808]: Remote socket (FD=14) initialized
2020.05.01 13:57:07 LOG7[12830:140495407703808]: SSL alert (read): warning: close notify
2020.05.01 13:57:07 LOG6[12830:140495407703808]: SSL closed (SSL_read)
2020.05.01 13:57:07 LOG7[12830:140495407703808]: Sent socket write shutdown
2020.05.01 13:57:07 LOG6[12830:140495407703808]: Read socket closed (hangup)
2020.05.01 13:57:07 LOG6[12830:140495407703808]: Write socket closed (hangup)
2020.05.01 13:57:07 LOG7[12830:140495407703808]: Sending close_notify alert
2020.05.01 13:57:07 LOG7[12830:140495407703808]: SSL alert (write): warning: close notify
2020.05.01 13:57:07 LOG6[12830:140495407703808]: SSL_shutdown successfully sent close_notify alert
2020.05.01 13:57:07 LOG5[12830:140495407703808]: Connection closed: 0 byte(s) sent to SSL, 0 byte(s) sent to socket
2020.05.01 13:57:07 LOG7[12830:140495407703808]: Remote socket (FD=14) closed
2020.05.01 13:57:07 LOG7[12830:140495407703808]: Local socket (FD=3) closed
2020.05.01 13:57:07 LOG7[12830:140495407703808]: Service [60666-v570] finished (0 left)
Вторая попытка клиента ... работает нормально, без 32-секундного ожидания и успешно завершается
2020.05.01 13:58:01 LOG7[12830:140495407708160]: Service [60666-v570] accepted (FD=3) from [redacted]
2020.05.01 13:58:01 LOG7[12830:140495407703808]: Service [60666-v570] started
2020.05.01 13:58:01 LOG7[12830:140495407703808]: Waiting for a libwrap process
2020.05.01 13:58:01 LOG7[12830:140495407703808]: Acquired libwrap process #0
2020.05.01 13:58:01 LOG7[12830:140495407703808]: Releasing libwrap process #0
2020.05.01 13:58:01 LOG7[12830:140495407703808]: Released libwrap process #0
2020.05.01 13:58:01 LOG7[12830:140495407703808]: Service [60666-v570] permitted by libwrap from [redacted]
2020.05.01 13:58:01 LOG5[12830:140495407703808]: Service [60666-v570] accepted connection from [redacted]
2020.05.01 13:58:01 LOG7[12830:140495407703808]: SSL state (accept): before/accept initialization
2020.05.01 13:58:01 LOG7[12830:140495407703808]: SNI: no virtual services defined
2020.05.01 13:58:01 LOG7[12830:140495407703808]: SSL state (accept): SSLv3 read client hello A
2020.05.01 13:58:01 LOG7[12830:140495407703808]: SSL state (accept): SSLv3 write server hello A
2020.05.01 13:58:01 LOG7[12830:140495407703808]: SSL state (accept): SSLv3 write change cipher spec A
2020.05.01 13:58:01 LOG7[12830:140495407703808]: SSL state (accept): SSLv3 write finished A
2020.05.01 13:58:01 LOG7[12830:140495407703808]: SSL state (accept): SSLv3 flush data
2020.05.01 13:58:02 LOG7[12830:140495407703808]: SSL state (accept): SSLv3 read finished A
2020.05.01 13:58:02 LOG7[12830:140495407703808]: 1 items in the session cache
2020.05.01 13:58:02 LOG7[12830:140495407703808]: 0 client connects (SSL_connect())
2020.05.01 13:58:02 LOG7[12830:140495407703808]: 0 client connects that finished
2020.05.01 13:58:02 LOG7[12830:140495407703808]: 0 client renegotiations requested
2020.05.01 13:58:02 LOG7[12830:140495407703808]: 2 server connects (SSL_accept())
2020.05.01 13:58:02 LOG7[12830:140495407703808]: 2 server connects that finished
2020.05.01 13:58:02 LOG7[12830:140495407703808]: 0 server renegotiations requested
2020.05.01 13:58:02 LOG7[12830:140495407703808]: 1 session cache hits
2020.05.01 13:58:02 LOG7[12830:140495407703808]: 0 external session cache hits
2020.05.01 13:58:02 LOG7[12830:140495407703808]: 0 session cache misses
2020.05.01 13:58:02 LOG7[12830:140495407703808]: 0 session cache timeouts
2020.05.01 13:58:02 LOG6[12830:140495407703808]: SSL accepted: previous session reused
2020.05.01 13:58:02 LOG6[12830:140495407703808]: local_bind succeeded on an ephemeral port
2020.05.01 13:58:02 LOG6[12830:140495407703808]: connect_blocking: connecting 127.0.0.1:50001
2020.05.01 13:58:02 LOG7[12830:140495407703808]: connect_blocking: s_poll_wait 127.0.0.1:50001: waiting 10 seconds
2020.05.01 13:58:02 LOG5[12830:140495407703808]: connect_blocking: connected 127.0.0.1:50001
2020.05.01 13:58:02 LOG5[12830:140495407703808]: Service [60666-v570] connected remote server from 127.0.0.66:42546
2020.05.01 13:58:02 LOG7[12830:140495407703808]: Remote socket (FD=14) initialized
2020.05.01 13:58:03 LOG6[12830:140495407703808]: Read socket closed (readsocket)
2020.05.01 13:58:03 LOG7[12830:140495407703808]: Sending close_notify alert
2020.05.01 13:58:03 LOG7[12830:140495407703808]: SSL alert (write): warning: close notify
2020.05.01 13:58:03 LOG6[12830:140495407703808]: SSL_shutdown successfully sent close_notify alert
2020.05.01 13:58:04 LOG7[12830:140495407703808]: SSL alert (read): warning: close notify
2020.05.01 13:58:04 LOG6[12830:140495407703808]: SSL closed (SSL_read)
2020.05.01 13:58:04 LOG7[12830:140495407703808]: Sent socket write shutdown
2020.05.01 13:58:04 LOG5[12830:140495407703808]: Connection closed: 40 byte(s) sent to SSL, 64 byte(s) sent to socket
2020.05.01 13:58:04 LOG7[12830:140495407703808]: Remote socket (FD=14) closed
2020.05.01 13:58:04 LOG7[12830:140495407703808]: Local socket (FD=3) closed
2020.05.01 13:58:04 LOG7[12830:140495407703808]: Service [60666-v570] finished (0 left)