Статус: Новичок
Группы: Участники
Зарегистрирован: 20.06.2019(UTC) Сообщений: 4 
|
Добрый день! Пытаюсь построить туннель до ФинЦЕРТ ЦБ. Насколько я понимаю, сам туннель строится, однако на любой запрос получаю ошибку "421 Misdirected Request". Ответ от stunnel: Код:<html>
<head>
<title>421 Misdirected Request</title>
</head>
<body bgcolor="white">
<center>
<h1>421 Misdirected Request</h1>
</center>
</body>
</html>
Конфиг: Код:pid=/opt/cprocsp/tmp/stunnel_cli.pid
output=/opt/cprocsp/tmp/stunnel_cli.log
socket = l:TCP_NODELAY=1
socket = r:TCP_NODELAY=1
debug = 7
foreground = yes
[https]
client = yes
accept = 0.0.0.0:8080
connect = zoe-lk.fincert.cbr.ru:443
verify = 1
Логи:
Код:2019.06.21 09:29:22 LOG5[9935:140350898767680]: stunnel 4.18 on x86_64-pc-linux-gnu
2019.06.21 09:29:22 LOG5[9935:140350898767680]: Threading:PTHREAD Sockets:POLL,IPv6 Auth:LIBWRAP
2019.06.21 09:29:22 LOG6[9935:140350898767680]: file ulimit = 1024 (can be changed with 'ulimit -n')
2019.06.21 09:29:22 LOG6[9935:140350898767680]: poll() used - no FD_SETSIZE limit for file descriptors
2019.06.21 09:29:22 LOG5[9935:140350898767680]: 0 clients allowed
2019.06.21 09:29:22 LOG7[9935:140350898767680]: FD 5 in non-blocking mode
2019.06.21 09:29:22 LOG7[9935:140350898767680]: FD 6 in non-blocking mode
2019.06.21 09:29:22 LOG7[9935:140350898767680]: FD 7 in non-blocking mode
2019.06.21 09:29:22 LOG7[9935:140350898767680]: SO_REUSEADDR option set on accept socket
2019.06.21 09:29:22 LOG7[9935:140350898767680]: https bound to 0.0.0.0:8080
2019.06.21 09:29:22 LOG7[9935:140350898767680]: Created pid file /opt/cprocsp/tmp/stunnel_cli.pid
2019.06.21 09:29:29 LOG7[9935:140350898767680]: https accepted FD=8 from 172.16.172.1:54739
2019.06.21 09:29:29 LOG7[9935:140350898759424]: client start
2019.06.21 09:29:29 LOG7[9935:140350898759424]: https started
2019.06.21 09:29:29 LOG7[9935:140350898759424]: FD 8 in non-blocking mode
2019.06.21 09:29:29 LOG7[9935:140350898759424]: TCP_NODELAY option set on local socket
2019.06.21 09:29:29 LOG7[9935:140350898759424]: FD 9 in non-blocking mode
2019.06.21 09:29:29 LOG7[9935:140350898759424]: FD 10 in non-blocking mode
2019.06.21 09:29:29 LOG7[9935:140350898767680]: https accepted FD=10 from 172.16.172.1:54740
2019.06.21 09:29:29 LOG7[9935:140350898759424]: Connection from 172.16.172.1:54739 permitted by libwrap
2019.06.21 09:29:29 LOG5[9935:140350898759424]: https connected from 172.16.172.1:54739
2019.06.21 09:29:29 LOG7[9935:140350898231040]: client start
2019.06.21 09:29:29 LOG7[9935:140350898231040]: https started
2019.06.21 09:29:29 LOG7[9935:140350898231040]: FD 10 in non-blocking mode
2019.06.21 09:29:29 LOG7[9935:140350898231040]: TCP_NODELAY option set on local socket
2019.06.21 09:29:29 LOG7[9935:140350898231040]: FD 11 in non-blocking mode
2019.06.21 09:29:29 LOG7[9935:140350898231040]: FD 12 in non-blocking mode
2019.06.21 09:29:29 LOG7[9935:140350898767680]: Cleaning up the signal pipe
2019.06.21 09:29:29 LOG6[9935:140350898767680]: Child process 9937 finished with code 0
2019.06.21 09:29:29 LOG7[9935:140350898231040]: Connection from 172.16.172.1:54740 permitted by libwrap
2019.06.21 09:29:29 LOG5[9935:140350898231040]: https connected from 172.16.172.1:54740
2019.06.21 09:29:29 LOG7[9935:140350898767680]: Cleaning up the signal pipe
2019.06.21 09:29:29 LOG6[9935:140350898767680]: Child process 9940 finished with code 0
2019.06.21 09:29:29 LOG7[9935:140350898759424]: FD 14 in non-blocking mode
2019.06.21 09:29:29 LOG7[9935:140350898759424]: https connecting
2019.06.21 09:29:29 LOG7[9935:140350898759424]: connect_wait: waiting 10 seconds
2019.06.21 09:29:29 LOG7[9935:140350898231040]: FD 17 in non-blocking mode
2019.06.21 09:29:29 LOG7[9935:140350898231040]: https connecting
2019.06.21 09:29:29 LOG7[9935:140350898231040]: connect_wait: waiting 10 seconds
2019.06.21 09:29:29 LOG7[9935:140350898231040]: connect_wait: connected
2019.06.21 09:29:29 LOG7[9935:140350898231040]: Remote FD=17 initialized
2019.06.21 09:29:29 LOG7[9935:140350898231040]: TCP_NODELAY option set on remote socket
2019.06.21 09:29:29 LOG7[9935:140350898231040]: start SSPI connect
2019.06.21 09:29:29 LOG3[9935:140350898231040]: Credentials complete
2019.06.21 09:29:29 LOG7[9935:140350898231040]: 129 bytes of handshake data sent
2019.06.21 09:29:29 LOG5[9935:140350898231040]: 1460 bytes of handshake(in handshake loop) data received.
2019.06.21 09:29:29 LOG5[9935:140350898231040]: 700 bytes of handshake(in handshake loop) data received.
2019.06.21 09:29:29 LOG5[9935:140350898231040]: 210 bytes of handshake data sent
2019.06.21 09:29:29 LOG7[9935:140350898759424]: connect_wait: connected
2019.06.21 09:29:29 LOG7[9935:140350898759424]: Remote FD=14 initialized
2019.06.21 09:29:29 LOG7[9935:140350898759424]: TCP_NODELAY option set on remote socket
2019.06.21 09:29:29 LOG7[9935:140350898759424]: start SSPI connect
2019.06.21 09:29:29 LOG3[9935:140350898759424]: Credentials complete
2019.06.21 09:29:29 LOG7[9935:140350898759424]: 129 bytes of handshake data sent
2019.06.21 09:29:29 LOG5[9935:140350898231040]: 31 bytes of handshake(in handshake loop) data received.
2019.06.21 09:29:29 LOG5[9935:140350898231040]: Handshake was successful
2019.06.21 09:29:29 LOG5[9935:140350898231040]: PerformClientHandshake finish
2019.06.21 09:29:29 LOG5[9935:140350898231040]: Server subject: I=00000, INN=007702235133, OGRN=1037700013020, O=БАНК РОССИИ, STREET="ул. Неглинная, д.12", L=Москва, S=77 г. Москва, C=RU, CN=zoe-lk.fincert.cbr.ru
2019.06.21 09:29:29 LOG5[9935:140350898231040]: Server issuer: OGRN=1127746036494, INN=007722766598, C=RU, S=77 Москва, L=Москва, STREET="ул. Авиамоторная, д. 8А, стр. 5", O="ЗАО ""Национальный удостоверяющий центр""", CN="ЗАО ""Национальный удостоверяющий центр"""
2019.06.21 09:29:29 LOG5[9935:140350898759424]: 2160 bytes of handshake(in handshake loop) data received.
2019.06.21 09:29:29 LOG5[9935:140350898759424]: 210 bytes of handshake data sent
2019.06.21 09:29:29 LOG5[9935:140350898759424]: 31 bytes of handshake(in handshake loop) data received.
2019.06.21 09:29:29 LOG5[9935:140350898759424]: Handshake was successful
2019.06.21 09:29:29 LOG5[9935:140350898759424]: PerformClientHandshake finish
2019.06.21 09:29:29 LOG5[9935:140350898759424]: Server subject: I=00000, INN=007702235133, OGRN=1037700013020, O=БАНК РОССИИ, STREET="ул. Неглинная, д.12", L=Москва, S=77 г. Москва, C=RU, CN=zoe-lk.fincert.cbr.ru
2019.06.21 09:29:29 LOG5[9935:140350898759424]: Server issuer: OGRN=1127746036494, INN=007722766598, C=RU, S=77 Москва, L=Москва, STREET="ул. Авиамоторная, д. 8А, стр. 5", O="ЗАО ""Национальный удостоверяющий центр""", CN="ЗАО ""Национальный удостоверяющий центр"""
2019.06.21 09:29:29 LOG5[9935:140350898231040]: No error on CertGetCertificateChain
2019.06.21 09:29:29 LOG5[9935:140350898231040]: Protocol: TLS1
2019.06.21 09:29:29 LOG5[9935:140350898231040]: Cipher: Gost 28147-89
2019.06.21 09:29:29 LOG5[9935:140350898231040]: Cipher strength: 256
2019.06.21 09:29:29 LOG5[9935:140350898231040]: Hash: Gost R 34.11-94
2019.06.21 09:29:29 LOG5[9935:140350898231040]: Hash strength: 256
2019.06.21 09:29:29 LOG5[9935:140350898231040]: Key exchange: 0xaa25
2019.06.21 09:29:29 LOG5[9935:140350898231040]: Key exchange strength: 512
2019.06.21 09:29:29 LOG7[9935:140350898231040]: Handshake_done
2019.06.21 09:29:29 LOG7[9935:140350898231040]: add ssl read socket to pool
2019.06.21 09:29:29 LOG7[9935:140350898231040]: ssl_rd = 1, c->ssl_ptr = 0,c->sock_ptr=0,want_rd = 0
2019.06.21 09:29:29 LOG7[9935:140350898231040]: Enter pool section on transfer
2019.06.21 09:29:29 LOG7[9935:140350898231040]: !!!!!Call s_poll_wait with timeout = -1 ((sock_rd && ssl_rd)=1) c->ssl_ptr = 0 c->sock_ptr=0
2019.06.21 09:29:29 LOG5[9935:140350898759424]: No error on CertGetCertificateChain
2019.06.21 09:29:29 LOG5[9935:140350898759424]: Protocol: TLS1
2019.06.21 09:29:29 LOG5[9935:140350898759424]: Cipher: Gost 28147-89
2019.06.21 09:29:29 LOG5[9935:140350898759424]: Cipher strength: 256
2019.06.21 09:29:29 LOG5[9935:140350898759424]: Hash: Gost R 34.11-94
2019.06.21 09:29:29 LOG5[9935:140350898759424]: Hash strength: 256
2019.06.21 09:29:29 LOG5[9935:140350898759424]: Key exchange: 0xaa25
2019.06.21 09:29:29 LOG5[9935:140350898759424]: Key exchange strength: 512
2019.06.21 09:29:29 LOG7[9935:140350898759424]: Handshake_done
2019.06.21 09:29:29 LOG7[9935:140350898759424]: add ssl read socket to pool
2019.06.21 09:29:29 LOG7[9935:140350898759424]: ssl_rd = 1, c->ssl_ptr = 0,c->sock_ptr=0,want_rd = 0
2019.06.21 09:29:29 LOG7[9935:140350898759424]: Enter pool section on transfer
2019.06.21 09:29:29 LOG7[9935:140350898759424]: !!!!!Call s_poll_wait with timeout = -1 ((sock_rd && ssl_rd)=1) c->ssl_ptr = 0 c->sock_ptr=0
2019.06.21 09:29:29 LOG7[9935:140350898759424]: data reciev from socket = 429
2019.06.21 09:29:29 LOG7[9935:140350898759424]: add ssl read socket to pool
2019.06.21 09:29:29 LOG7[9935:140350898759424]: ssl_rd = 1, c->ssl_ptr = 0,c->sock_ptr=429,want_rd = 0
2019.06.21 09:29:29 LOG7[9935:140350898759424]: Enter pool section on transfer
2019.06.21 09:29:29 LOG7[9935:140350898759424]: !!!!!Call s_poll_wait with timeout = -1 ((sock_rd && ssl_rd)=1) c->ssl_ptr = 0 c->sock_ptr=1ad
2019.06.21 09:29:29 LOG5[9935:140350898759424]: SSPI_write start
2019.06.21 09:29:29 LOG7[9935:140350898759424]: SSPI_write data is GET
2019.06.21 09:29:29 LOG7[9935:140350898759424]: send all data after encrypt
2019.06.21 09:29:29 LOG7[9935:140350898759424]: data send to ssl_socket =429
2019.06.21 09:29:29 LOG7[9935:140350898759424]: add ssl read socket to pool
2019.06.21 09:29:29 LOG7[9935:140350898759424]: ssl_rd = 1, c->ssl_ptr = 0,c->sock_ptr=0,want_rd = 0
2019.06.21 09:29:29 LOG7[9935:140350898759424]: Enter pool section on transfer
2019.06.21 09:29:29 LOG7[9935:140350898759424]: !!!!!Call s_poll_wait with timeout = -1 ((sock_rd && ssl_rd)=1) c->ssl_ptr = 0 c->sock_ptr=0
2019.06.21 09:29:29 LOG7[9935:140350898759424]: SSPI_read start
2019.06.21 09:29:29 LOG7[9935:140350898759424]: recv ok on SSPI_read err= 324
2019.06.21 09:29:29 LOG5[9935:140350898759424]: Received 324 bytes from ssl socket
2019.06.21 09:29:29 LOG7[9935:140350898759424]: SSPI_read data in ssl_buff is HTTP
2019.06.21 09:29:29 LOG7[9935:140350898759424]: data read from ssl_sock =315
2019.06.21 09:29:29 LOG7[9935:140350898759424]: add ssl read socket to pool
2019.06.21 09:29:29 LOG7[9935:140350898759424]: ssl_rd = 1, c->ssl_ptr = 315,c->sock_ptr=0,want_rd = 0
2019.06.21 09:29:29 LOG7[9935:140350898759424]: add write socket to poll
2019.06.21 09:29:29 LOG7[9935:140350898759424]: Enter pool section on transfer
2019.06.21 09:29:29 LOG7[9935:140350898759424]: !!!!!Call s_poll_wait with timeout = -1 ((sock_rd && ssl_rd)=1) c->ssl_ptr = 13b c->sock_ptr=0
2019.06.21 09:29:29 LOG7[9935:140350898759424]: data send to socket = 315
2019.06.21 09:29:29 LOG7[9935:140350898759424]: SSPI_read start
2019.06.21 09:29:29 LOG7[9935:140350898759424]: recv ok on SSPI_read err= 0
2019.06.21 09:29:29 LOG3[9935:140350898759424]: recv return 0 and ask more but there is not complete data for decrypt. Peer disconnected?
2019.06.21 09:29:29 LOG5[9935:140350898759424]: SSPI_read: read socket closed
2019.06.21 09:29:29 LOG7[9935:140350898759424]: Socket write shutdown
2019.06.21 09:29:29 LOG7[9935:140350898759424]: c->ssl_ptr = 0
2019.06.21 09:29:29 LOG7[9935:140350898759424]: Enter pool section on transfer
2019.06.21 09:29:29 LOG7[9935:140350898759424]: !!!!!Call s_poll_wait with timeout = 60 ((sock_rd && ssl_rd)=0) c->ssl_ptr = 0 c->sock_ptr=0
2019.06.21 09:29:29 LOG7[9935:140350898759424]: Socket closed on read
2019.06.21 09:29:29 LOG7[9935:140350898759424]: SSL write shutdown
2019.06.21 09:29:29 LOG7[9935:140350898759424]: Enter pool section on transfer
2019.06.21 09:29:29 LOG7[9935:140350898759424]: !!!!!Call s_poll_wait with timeout = 60 ((sock_rd && ssl_rd)=0) c->ssl_ptr = 0 c->sock_ptr=0
2019.06.21 09:29:29 LOG7[9935:140350898231040]: data reciev from socket = 429
2019.06.21 09:29:29 LOG7[9935:140350898231040]: add ssl read socket to pool
2019.06.21 09:29:29 LOG7[9935:140350898231040]: ssl_rd = 1, c->ssl_ptr = 0,c->sock_ptr=429,want_rd = 0
2019.06.21 09:29:29 LOG7[9935:140350898231040]: Enter pool section on transfer
2019.06.21 09:29:29 LOG7[9935:140350898231040]: !!!!!Call s_poll_wait with timeout = -1 ((sock_rd && ssl_rd)=1) c->ssl_ptr = 0 c->sock_ptr=1ad
2019.06.21 09:29:29 LOG5[9935:140350898231040]: SSPI_write start
2019.06.21 09:29:29 LOG7[9935:140350898231040]: SSPI_write data is GET
2019.06.21 09:29:29 LOG7[9935:140350898231040]: send all data after encrypt
2019.06.21 09:29:29 LOG7[9935:140350898231040]: data send to ssl_socket =429
2019.06.21 09:29:29 LOG7[9935:140350898231040]: add ssl read socket to pool
2019.06.21 09:29:29 LOG7[9935:140350898231040]: ssl_rd = 1, c->ssl_ptr = 0,c->sock_ptr=0,want_rd = 0
2019.06.21 09:29:29 LOG7[9935:140350898231040]: Enter pool section on transfer
2019.06.21 09:29:29 LOG7[9935:140350898231040]: !!!!!Call s_poll_wait with timeout = -1 ((sock_rd && ssl_rd)=1) c->ssl_ptr = 0 c->sock_ptr=0
2019.06.21 09:29:29 LOG5[9935:140350898759424]: 11 bytes of close_notify data sent
2019.06.21 09:29:29 LOG6[9935:140350898759424]: SSL_shutdown successfully sent close_notify
2019.06.21 09:29:29 LOG5[9935:140350898759424]: Connection closed: 429 bytes sent to SSL, 315 bytes sent to socket
2019.06.21 09:29:29 LOG7[9935:140350898759424]: free Buffers
2019.06.21 09:29:29 LOG7[9935:140350898759424]: delete c->hContext
2019.06.21 09:29:29 LOG7[9935:140350898759424]: delete c->hClientCreds
2019.06.21 09:29:29 LOG5[9935:140350898759424]: incomp_mess = 2, extra_data = 0
2019.06.21 09:29:29 LOG7[9935:140350898759424]: https finished (1 left)
2019.06.21 09:29:30 LOG7[9935:140350898231040]: SSPI_read start
2019.06.21 09:29:30 LOG7[9935:140350898231040]: recv ok on SSPI_read err= 324
2019.06.21 09:29:30 LOG5[9935:140350898231040]: Received 324 bytes from ssl socket
2019.06.21 09:29:30 LOG7[9935:140350898231040]: SSPI_read data in ssl_buff is HTTP
2019.06.21 09:29:30 LOG7[9935:140350898231040]: data read from ssl_sock =315
2019.06.21 09:29:30 LOG7[9935:140350898231040]: add ssl read socket to pool
2019.06.21 09:29:30 LOG7[9935:140350898231040]: ssl_rd = 1, c->ssl_ptr = 315,c->sock_ptr=0,want_rd = 0
2019.06.21 09:29:30 LOG7[9935:140350898231040]: add write socket to poll
2019.06.21 09:29:30 LOG7[9935:140350898231040]: Enter pool section on transfer
2019.06.21 09:29:30 LOG7[9935:140350898231040]: !!!!!Call s_poll_wait with timeout = -1 ((sock_rd && ssl_rd)=1) c->ssl_ptr = 13b c->sock_ptr=0
2019.06.21 09:29:30 LOG7[9935:140350898231040]: data send to socket = 315
2019.06.21 09:29:30 LOG7[9935:140350898231040]: SSPI_read start
2019.06.21 09:29:30 LOG7[9935:140350898231040]: recv ok on SSPI_read err= 0
2019.06.21 09:29:30 LOG3[9935:140350898231040]: recv return 0 and ask more but there is not complete data for decrypt. Peer disconnected?
2019.06.21 09:29:30 LOG5[9935:140350898231040]: SSPI_read: read socket closed
2019.06.21 09:29:30 LOG7[9935:140350898231040]: Socket write shutdown
2019.06.21 09:29:30 LOG7[9935:140350898231040]: c->ssl_ptr = 0
2019.06.21 09:29:30 LOG7[9935:140350898231040]: Enter pool section on transfer
2019.06.21 09:29:30 LOG7[9935:140350898231040]: !!!!!Call s_poll_wait with timeout = 60 ((sock_rd && ssl_rd)=0) c->ssl_ptr = 0 c->sock_ptr=0
2019.06.21 09:29:30 LOG7[9935:140350898231040]: Socket closed on read
2019.06.21 09:29:30 LOG7[9935:140350898231040]: SSL write shutdown
2019.06.21 09:29:30 LOG7[9935:140350898231040]: Enter pool section on transfer
2019.06.21 09:29:30 LOG7[9935:140350898231040]: !!!!!Call s_poll_wait with timeout = 60 ((sock_rd && ssl_rd)=0) c->ssl_ptr = 0 c->sock_ptr=0
2019.06.21 09:29:30 LOG5[9935:140350898231040]: 11 bytes of close_notify data sent
2019.06.21 09:29:30 LOG6[9935:140350898231040]: SSL_shutdown successfully sent close_notify
2019.06.21 09:29:30 LOG5[9935:140350898231040]: Connection closed: 429 bytes sent to SSL, 315 bytes sent to socket
2019.06.21 09:29:30 LOG7[9935:140350898231040]: free Buffers
2019.06.21 09:29:30 LOG7[9935:140350898231040]: delete c->hContext
2019.06.21 09:29:30 LOG7[9935:140350898231040]: delete c->hClientCreds
2019.06.21 09:29:30 LOG5[9935:140350898231040]: incomp_mess = 2, extra_data = 1
2019.06.21 09:29:30 LOG7[9935:140350898231040]: https finished (0 left)
2019.06.21 09:29:30 LOG7[9935:140350898767680]: https accepted FD=8 from 172.16.172.1:54743
2019.06.21 09:29:30 LOG7[9935:140350898231040]: client start
2019.06.21 09:29:30 LOG7[9935:140350898231040]: https started
2019.06.21 09:29:30 LOG7[9935:140350898231040]: FD 8 in non-blocking mode
2019.06.21 09:29:30 LOG7[9935:140350898231040]: TCP_NODELAY option set on local socket
2019.06.21 09:29:30 LOG7[9935:140350898231040]: FD 9 in non-blocking mode
2019.06.21 09:29:30 LOG7[9935:140350898231040]: FD 10 in non-blocking mode
2019.06.21 09:29:30 LOG7[9935:140350898231040]: Connection from 172.16.172.1:54743 permitted by libwrap
2019.06.21 09:29:30 LOG5[9935:140350898231040]: https connected from 172.16.172.1:54743
2019.06.21 09:29:30 LOG7[9935:140350898231040]: FD 13 in non-blocking mode
2019.06.21 09:29:30 LOG7[9935:140350898231040]: https connecting
2019.06.21 09:29:30 LOG7[9935:140350898231040]: connect_wait: waiting 10 seconds
2019.06.21 09:29:30 LOG7[9935:140350898767680]: Cleaning up the signal pipe
2019.06.21 09:29:30 LOG6[9935:140350898767680]: Child process 9943 finished with code 0
2019.06.21 09:29:30 LOG7[9935:140350898231040]: connect_wait: connected
2019.06.21 09:29:30 LOG7[9935:140350898231040]: Remote FD=13 initialized
2019.06.21 09:29:30 LOG7[9935:140350898231040]: TCP_NODELAY option set on remote socket
2019.06.21 09:29:30 LOG7[9935:140350898231040]: start SSPI connect
2019.06.21 09:29:30 LOG3[9935:140350898231040]: Credentials complete
2019.06.21 09:29:30 LOG7[9935:140350898231040]: 125 bytes of handshake data sent
2019.06.21 09:29:30 LOG5[9935:140350898231040]: 1460 bytes of handshake(in handshake loop) data received.
2019.06.21 09:29:30 LOG5[9935:140350898231040]: 700 bytes of handshake(in handshake loop) data received.
2019.06.21 09:29:30 LOG5[9935:140350898231040]: 210 bytes of handshake data sent
2019.06.21 09:29:30 LOG5[9935:140350898231040]: 31 bytes of handshake(in handshake loop) data received.
2019.06.21 09:29:30 LOG5[9935:140350898231040]: Handshake was successful
2019.06.21 09:29:30 LOG5[9935:140350898231040]: PerformClientHandshake finish
2019.06.21 09:29:30 LOG5[9935:140350898231040]: Server subject: I=00000, INN=007702235133, OGRN=1037700013020, O=БАНК РОССИИ, STREET="ул. Неглинная, д.12", L=Москва, S=77 г. Москва, C=RU, CN=zoe-lk.fincert.cbr.ru
2019.06.21 09:29:30 LOG5[9935:140350898231040]: Server issuer: OGRN=1127746036494, INN=007722766598, C=RU, S=77 Москва, L=Москва, STREET="ул. Авиамоторная, д. 8А, стр. 5", O="ЗАО ""Национальный удостоверяющий центр""", CN="ЗАО ""Национальный удостоверяющий центр"""
2019.06.21 09:29:30 LOG5[9935:140350898231040]: No error on CertGetCertificateChain
2019.06.21 09:29:30 LOG5[9935:140350898231040]: Protocol: TLS1
2019.06.21 09:29:30 LOG5[9935:140350898231040]: Cipher: Gost 28147-89
2019.06.21 09:29:30 LOG5[9935:140350898231040]: Cipher strength: 256
2019.06.21 09:29:30 LOG5[9935:140350898231040]: Hash: Gost R 34.11-94
2019.06.21 09:29:30 LOG5[9935:140350898231040]: Hash strength: 256
2019.06.21 09:29:30 LOG5[9935:140350898231040]: Key exchange: 0xaa25
2019.06.21 09:29:30 LOG5[9935:140350898231040]: Key exchange strength: 512
2019.06.21 09:29:30 LOG7[9935:140350898231040]: Handshake_done
2019.06.21 09:29:30 LOG7[9935:140350898231040]: add ssl read socket to pool
2019.06.21 09:29:30 LOG7[9935:140350898231040]: ssl_rd = 1, c->ssl_ptr = 0,c->sock_ptr=0,want_rd = 0
2019.06.21 09:29:30 LOG7[9935:140350898231040]: Enter pool section on transfer
2019.06.21 09:29:30 LOG7[9935:140350898231040]: !!!!!Call s_poll_wait with timeout = -1 ((sock_rd && ssl_rd)=1) c->ssl_ptr = 0 c->sock_ptr=0
2019.06.21 09:29:30 LOG7[9935:140350898231040]: data reciev from socket = 418
2019.06.21 09:29:30 LOG7[9935:140350898231040]: add ssl read socket to pool
2019.06.21 09:29:30 LOG7[9935:140350898231040]: ssl_rd = 1, c->ssl_ptr = 0,c->sock_ptr=418,want_rd = 0
2019.06.21 09:29:30 LOG7[9935:140350898231040]: Enter pool section on transfer
2019.06.21 09:29:30 LOG7[9935:140350898231040]: !!!!!Call s_poll_wait with timeout = -1 ((sock_rd && ssl_rd)=1) c->ssl_ptr = 0 c->sock_ptr=1a2
2019.06.21 09:29:30 LOG5[9935:140350898231040]: SSPI_write start
2019.06.21 09:29:30 LOG7[9935:140350898231040]: SSPI_write data is GET
2019.06.21 09:29:30 LOG7[9935:140350898231040]: send all data after encrypt
2019.06.21 09:29:30 LOG7[9935:140350898231040]: data send to ssl_socket =418
2019.06.21 09:29:30 LOG7[9935:140350898231040]: add ssl read socket to pool
2019.06.21 09:29:30 LOG7[9935:140350898231040]: ssl_rd = 1, c->ssl_ptr = 0,c->sock_ptr=0,want_rd = 0
2019.06.21 09:29:30 LOG7[9935:140350898231040]: Enter pool section on transfer
2019.06.21 09:29:30 LOG7[9935:140350898231040]: !!!!!Call s_poll_wait with timeout = -1 ((sock_rd && ssl_rd)=1) c->ssl_ptr = 0 c->sock_ptr=0
2019.06.21 09:29:30 LOG7[9935:140350898231040]: SSPI_read start
2019.06.21 09:29:30 LOG7[9935:140350898231040]: recv ok on SSPI_read err= 324
2019.06.21 09:29:30 LOG5[9935:140350898231040]: Received 324 bytes from ssl socket
2019.06.21 09:29:30 LOG7[9935:140350898231040]: SSPI_read data in ssl_buff is HTTP
2019.06.21 09:29:30 LOG7[9935:140350898231040]: data read from ssl_sock =315
2019.06.21 09:29:30 LOG7[9935:140350898231040]: add ssl read socket to pool
2019.06.21 09:29:30 LOG7[9935:140350898231040]: ssl_rd = 1, c->ssl_ptr = 315,c->sock_ptr=0,want_rd = 0
2019.06.21 09:29:30 LOG7[9935:140350898231040]: add write socket to poll
2019.06.21 09:29:30 LOG7[9935:140350898231040]: Enter pool section on transfer
2019.06.21 09:29:30 LOG7[9935:140350898231040]: !!!!!Call s_poll_wait with timeout = -1 ((sock_rd && ssl_rd)=1) c->ssl_ptr = 13b c->sock_ptr=0
2019.06.21 09:29:30 LOG7[9935:140350898231040]: data send to socket = 315
2019.06.21 09:29:30 LOG7[9935:140350898231040]: SSPI_read start
2019.06.21 09:29:30 LOG7[9935:140350898231040]: recv ok on SSPI_read err= 0
2019.06.21 09:29:30 LOG3[9935:140350898231040]: recv return 0 and ask more but there is not complete data for decrypt. Peer disconnected?
2019.06.21 09:29:30 LOG5[9935:140350898231040]: SSPI_read: read socket closed
2019.06.21 09:29:30 LOG7[9935:140350898231040]: Socket write shutdown
2019.06.21 09:29:30 LOG7[9935:140350898231040]: c->ssl_ptr = 0
2019.06.21 09:29:30 LOG7[9935:140350898231040]: Enter pool section on transfer
2019.06.21 09:29:30 LOG7[9935:140350898231040]: !!!!!Call s_poll_wait with timeout = 60 ((sock_rd && ssl_rd)=0) c->ssl_ptr = 0 c->sock_ptr=0
2019.06.21 09:29:30 LOG7[9935:140350898231040]: Socket closed on read
2019.06.21 09:29:30 LOG7[9935:140350898231040]: SSL write shutdown
2019.06.21 09:29:30 LOG7[9935:140350898231040]: Enter pool section on transfer
2019.06.21 09:29:30 LOG7[9935:140350898231040]: !!!!!Call s_poll_wait with timeout = 60 ((sock_rd && ssl_rd)=0) c->ssl_ptr = 0 c->sock_ptr=0
2019.06.21 09:29:30 LOG5[9935:140350898231040]: 11 bytes of close_notify data sent
2019.06.21 09:29:30 LOG6[9935:140350898231040]: SSL_shutdown successfully sent close_notify
2019.06.21 09:29:30 LOG5[9935:140350898231040]: Connection closed: 418 bytes sent to SSL, 315 bytes sent to socket
2019.06.21 09:29:30 LOG7[9935:140350898231040]: free Buffers
2019.06.21 09:29:30 LOG7[9935:140350898231040]: delete c->hContext
2019.06.21 09:29:30 LOG7[9935:140350898231040]: delete c->hClientCreds
2019.06.21 09:29:30 LOG5[9935:140350898231040]: incomp_mess = 2, extra_data = 1
2019.06.21 09:29:30 LOG7[9935:140350898231040]: https finished (0 left)
2019.06.21 09:29:30 LOG7[9935:140350898767680]: https accepted FD=8 from 172.16.172.1:54745
2019.06.21 09:29:30 LOG7[9935:140350898231040]: client start
2019.06.21 09:29:30 LOG7[9935:140350898231040]: https started
2019.06.21 09:29:30 LOG7[9935:140350898231040]: FD 8 in non-blocking mode
2019.06.21 09:29:30 LOG7[9935:140350898231040]: TCP_NODELAY option set on local socket
2019.06.21 09:29:30 LOG7[9935:140350898231040]: FD 9 in non-blocking mode
2019.06.21 09:29:30 LOG7[9935:140350898231040]: FD 10 in non-blocking mode
2019.06.21 09:29:30 LOG7[9935:140350898231040]: Connection from 172.16.172.1:54745 permitted by libwrap
2019.06.21 09:29:30 LOG5[9935:140350898231040]: https connected from 172.16.172.1:54745
2019.06.21 09:29:30 LOG7[9935:140350898231040]: FD 13 in non-blocking mode
2019.06.21 09:29:30 LOG7[9935:140350898231040]: https connecting
2019.06.21 09:29:30 LOG7[9935:140350898231040]: connect_wait: waiting 10 seconds
2019.06.21 09:29:30 LOG7[9935:140350898767680]: Cleaning up the signal pipe
2019.06.21 09:29:30 LOG6[9935:140350898767680]: Child process 9945 finished with code 0
2019.06.21 09:29:30 LOG7[9935:140350898231040]: connect_wait: connected
2019.06.21 09:29:30 LOG7[9935:140350898231040]: Remote FD=13 initialized
2019.06.21 09:29:30 LOG7[9935:140350898231040]: TCP_NODELAY option set on remote socket
2019.06.21 09:29:30 LOG7[9935:140350898231040]: start SSPI connect
2019.06.21 09:29:30 LOG3[9935:140350898231040]: Credentials complete
2019.06.21 09:29:30 LOG7[9935:140350898231040]: 125 bytes of handshake data sent
2019.06.21 09:29:30 LOG5[9935:140350898231040]: 2160 bytes of handshake(in handshake loop) data received.
2019.06.21 09:29:30 LOG5[9935:140350898231040]: 210 bytes of handshake data sent
2019.06.21 09:29:30 LOG5[9935:140350898231040]: 31 bytes of handshake(in handshake loop) data received.
2019.06.21 09:29:30 LOG5[9935:140350898231040]: Handshake was successful
2019.06.21 09:29:30 LOG5[9935:140350898231040]: PerformClientHandshake finish
2019.06.21 09:29:30 LOG5[9935:140350898231040]: Server subject: I=00000, INN=007702235133, OGRN=1037700013020, O=БАНК РОССИИ, STREET="ул. Неглинная, д.12", L=Москва, S=77 г. Москва, C=RU, CN=zoe-lk.fincert.cbr.ru
2019.06.21 09:29:30 LOG5[9935:140350898231040]: Server issuer: OGRN=1127746036494, INN=007722766598, C=RU, S=77 Москва, L=Москва, STREET="ул. Авиамоторная, д. 8А, стр. 5", O="ЗАО ""Национальный удостоверяющий центр""", CN="ЗАО ""Национальный удостоверяющий центр"""
2019.06.21 09:29:30 LOG5[9935:140350898231040]: No error on CertGetCertificateChain
2019.06.21 09:29:30 LOG5[9935:140350898231040]: Protocol: TLS1
2019.06.21 09:29:30 LOG5[9935:140350898231040]: Cipher: Gost 28147-89
2019.06.21 09:29:30 LOG5[9935:140350898231040]: Cipher strength: 256
2019.06.21 09:29:30 LOG5[9935:140350898231040]: Hash: Gost R 34.11-94
2019.06.21 09:29:30 LOG5[9935:140350898231040]: Hash strength: 256
2019.06.21 09:29:30 LOG5[9935:140350898231040]: Key exchange: 0xaa25
2019.06.21 09:29:30 LOG5[9935:140350898231040]: Key exchange strength: 512
2019.06.21 09:29:30 LOG7[9935:140350898231040]: Handshake_done
2019.06.21 09:29:30 LOG7[9935:140350898231040]: add ssl read socket to pool
2019.06.21 09:29:30 LOG7[9935:140350898231040]: ssl_rd = 1, c->ssl_ptr = 0,c->sock_ptr=0,want_rd = 0
2019.06.21 09:29:30 LOG7[9935:140350898231040]: Enter pool section on transfer
2019.06.21 09:29:30 LOG7[9935:140350898231040]: !!!!!Call s_poll_wait with timeout = -1 ((sock_rd && ssl_rd)=1) c->ssl_ptr = 0 c->sock_ptr=0
2019.06.21 09:29:30 LOG7[9935:140350898231040]: data reciev from socket = 418
2019.06.21 09:29:30 LOG7[9935:140350898231040]: add ssl read socket to pool
2019.06.21 09:29:30 LOG7[9935:140350898231040]: ssl_rd = 1, c->ssl_ptr = 0,c->sock_ptr=418,want_rd = 0
2019.06.21 09:29:30 LOG7[9935:140350898231040]: Enter pool section on transfer
2019.06.21 09:29:30 LOG7[9935:140350898231040]: !!!!!Call s_poll_wait with timeout = -1 ((sock_rd && ssl_rd)=1) c->ssl_ptr = 0 c->sock_ptr=1a2
2019.06.21 09:29:30 LOG5[9935:140350898231040]: SSPI_write start
2019.06.21 09:29:30 LOG7[9935:140350898231040]: SSPI_write data is GET
2019.06.21 09:29:30 LOG7[9935:140350898231040]: send all data after encrypt
2019.06.21 09:29:30 LOG7[9935:140350898231040]: data send to ssl_socket =418
2019.06.21 09:29:30 LOG7[9935:140350898231040]: add ssl read socket to pool
2019.06.21 09:29:30 LOG7[9935:140350898231040]: ssl_rd = 1, c->ssl_ptr = 0,c->sock_ptr=0,want_rd = 0
2019.06.21 09:29:30 LOG7[9935:140350898231040]: Enter pool section on transfer
2019.06.21 09:29:30 LOG7[9935:140350898231040]: !!!!!Call s_poll_wait with timeout = -1 ((sock_rd && ssl_rd)=1) c->ssl_ptr = 0 c->sock_ptr=0
2019.06.21 09:29:30 LOG7[9935:140350898231040]: SSPI_read start
2019.06.21 09:29:30 LOG7[9935:140350898231040]: recv ok on SSPI_read err= 324
2019.06.21 09:29:30 LOG5[9935:140350898231040]: Received 324 bytes from ssl socket
2019.06.21 09:29:30 LOG7[9935:140350898231040]: SSPI_read data in ssl_buff is HTTP
2019.06.21 09:29:30 LOG7[9935:140350898231040]: data read from ssl_sock =315
2019.06.21 09:29:30 LOG7[9935:140350898231040]: add ssl read socket to pool
2019.06.21 09:29:30 LOG7[9935:140350898231040]: ssl_rd = 1, c->ssl_ptr = 315,c->sock_ptr=0,want_rd = 0
2019.06.21 09:29:30 LOG7[9935:140350898231040]: add write socket to poll
2019.06.21 09:29:30 LOG7[9935:140350898231040]: Enter pool section on transfer
2019.06.21 09:29:30 LOG7[9935:140350898231040]: !!!!!Call s_poll_wait with timeout = -1 ((sock_rd && ssl_rd)=1) c->ssl_ptr = 13b c->sock_ptr=0
2019.06.21 09:29:30 LOG7[9935:140350898231040]: data send to socket = 315
2019.06.21 09:29:30 LOG7[9935:140350898231040]: SSPI_read start
2019.06.21 09:29:30 LOG7[9935:140350898231040]: recv ok on SSPI_read err= 0
2019.06.21 09:29:30 LOG3[9935:140350898231040]: recv return 0 and ask more but there is not complete data for decrypt. Peer disconnected?
2019.06.21 09:29:30 LOG5[9935:140350898231040]: SSPI_read: read socket closed
2019.06.21 09:29:30 LOG7[9935:140350898231040]: Socket write shutdown
2019.06.21 09:29:30 LOG7[9935:140350898231040]: c->ssl_ptr = 0
2019.06.21 09:29:30 LOG7[9935:140350898231040]: Enter pool section on transfer
2019.06.21 09:29:30 LOG7[9935:140350898231040]: !!!!!Call s_poll_wait with timeout = 60 ((sock_rd && ssl_rd)=0) c->ssl_ptr = 0 c->sock_ptr=0
2019.06.21 09:29:30 LOG7[9935:140350898231040]: Socket closed on read
2019.06.21 09:29:30 LOG7[9935:140350898231040]: SSL write shutdown
2019.06.21 09:29:30 LOG7[9935:140350898231040]: Enter pool section on transfer
2019.06.21 09:29:30 LOG7[9935:140350898231040]: !!!!!Call s_poll_wait with timeout = 60 ((sock_rd && ssl_rd)=0) c->ssl_ptr = 0 c->sock_ptr=0
2019.06.21 09:29:30 LOG5[9935:140350898231040]: 11 bytes of close_notify data sent
2019.06.21 09:29:30 LOG6[9935:140350898231040]: SSL_shutdown successfully sent close_notify
2019.06.21 09:29:30 LOG5[9935:140350898231040]: Connection closed: 418 bytes sent to SSL, 315 bytes sent to socket
2019.06.21 09:29:30 LOG7[9935:140350898231040]: free Buffers
2019.06.21 09:29:30 LOG7[9935:140350898231040]: delete c->hContext
2019.06.21 09:29:30 LOG7[9935:140350898231040]: delete c->hClientCreds
2019.06.21 09:29:30 LOG5[9935:140350898231040]: incomp_mess = 2, extra_data = 0
2019.06.21 09:29:30 LOG7[9935:140350898231040]: https finished (0 left)
2019.06.21 09:29:32 LOG3[9935:140350898767680]: Received signal 2; terminating
2019.06.21 09:29:32 LOG7[9935:140350898767680]: removing pid file /opt/cprocsp/tmp/stunnel_cli.pid
Не подскажете в чем может быть дело? Судя по логам, сертификаты получаются, Handshake проходит (в том числе с verify = 2), т.е. с удаленным хостом все ок. Отредактировано пользователем 21 июня 2019 г. 9:59:43(UTC)
| Причина: Не указана
|