This is an update to our original post at:
Our conclusions:
We have checked our SSL certificate at:
http://www.digicert.com/help/ and
https://www.ssllabs.com/ssltest/analyze.html
and do not see any issues but then we are not sure what to look for. There is nothing in the AN documentation about this so any help resolving this issue would be appreciated.
Thanks.
08-01-2012 12:36 PM
Thanks, @RichardH. Just to let you know that all transactions have been fine since we reported the issue; no changes our end at all.
08-14-2012 12:13 PM
I'm glad to hear you are no longer experiencing these issues since it was corrected.
08-16-2012 10:32 AM
Last night between 6:25 and 7:30PM PST we had two transactions that went awry. In both cases AN pulled the relay response URL as it normally does, but did not execute that page to return information to our site.
This happened last several weeks ago (reported in this thread) and had been fine ever since. I cannot believe it is our code (which has not changed) or server (we had other successful transactions at that time and again the URL was pulled from our server).
I continue to believe that AN has some DPM issues but never owns up to them or explains them -- this does not inspire confidence.
08-28-2012 10:14 AM
StephenS, I sent you a private message asking for some additional details regarding your issue.
08-28-2012 10:59 AM
I'm experiencing the same issue. The same code on a dev url (without https) works properly. Put it on https, and it gives the error. There's nothing in the logs that shows that a url was posted to from authorize.net. I'm using a DigiCert SSL behind nginx.
Richard, do you know if this is something I can fix on our end?
Thanks!
09-11-2012 05:46 AM
To elaborate, I found that there is a post request made, but it's failing to negotaite the handshake for the SSL. Any thoughts on this nginx log?
2012/09/11 13:14:41 [debug] 23649#0: post event 0000000002610EA8
2012/09/11 13:14:41 [debug] 23649#0: delete posted event 0000000002610EA8
2012/09/11 13:14:41 [debug] 23649#0: accept on 0.0.0.0:443, ready: 0
2012/09/11 13:14:41 [debug] 23649#0: posix_memalign: 00000000025E4B90:256 @16
2012/09/11 13:14:41 [debug] 23649#0: *9 accept: 64.94.118.193 fd:15
2012/09/11 13:14:41 [debug] 23649#0: *9 event timer add: 15: 60000:1347369341415
2012/09/11 13:14:41 [debug] 23649#0: *9 epoll add event: fd:15 op:1 ev:80000001
2012/09/11 13:14:41 [debug] 23649#0: *9 post event 0000000002610FE0
2012/09/11 13:14:41 [debug] 23649#0: *9 delete posted event 0000000002610FE0
2012/09/11 13:14:41 [debug] 23649#0: *9 malloc: 00000000025A9CA0:1296
2012/09/11 13:14:41 [debug] 23649#0: *9 posix_memalign: 00000000025E4CA0:256 @16
2012/09/11 13:14:41 [debug] 23649#0: *9 malloc: 0000000002646950:1024
2012/09/11 13:14:41 [debug] 23649#0: *9 posix_memalign: 0000000002646D60:4096 @16
2012/09/11 13:14:41 [debug] 23649#0: *9 http check ssl handshake
2012/09/11 13:14:41 [debug] 23649#0: *9 https ssl handshake: 0x16
2012/09/11 13:14:41 [debug] 23649#0: *9 SSL_do_handshake: -1
2012/09/11 13:14:41 [debug] 23649#0: *9 SSL_get_error: 2
2012/09/11 13:14:41 [debug] 23649#0: *9 post event 0000000002610FE0
2012/09/11 13:14:41 [debug] 23649#0: *9 delete posted event 0000000002610FE0
2012/09/11 13:14:41 [debug] 23649#0: *9 SSL handshake handler: 0
2012/09/11 13:14:41 [debug] 23649#0: *9 ssl new session: 4C624D45:32:119
2012/09/11 13:14:41 [debug] 23649#0: *9 SSL_do_handshake: 1
2012/09/11 13:14:41 [debug] 23649#0: *9 SSL: TLSv1, cipher: "RC4-SHA SSLv3 Kx=RSA Au=RSA Enc=RC4(128) Mac=SHA1"
2012/09/11 13:14:41 [debug] 23649#0: *9 http process request line
2012/09/11 13:14:41 [debug] 23649#0: *9 SSL_read: -1
2012/09/11 13:14:41 [debug] 23649#0: *9 SSL_get_error: 2
2012/09/11 13:14:42 [debug] 23649#0: *9 post event 0000000002610FE0
2012/09/11 13:14:42 [debug] 23649#0: *9 delete posted event 0000000002610FE0
2012/09/11 13:14:42 [debug] 23649#0: *9 http process request line
2012/09/11 13:14:42 [debug] 23649#0: *9 SSL_read: 0
2012/09/11 13:14:42 [debug] 23649#0: *9 SSL_get_error: 5
2012/09/11 13:14:42 [debug] 23649#0: *9 peer shutdown SSL cleanly
2012/09/11 13:14:42 [info] 23649#0: *9 client closed prematurely connection while SSL handshaking, client: 64.94.118.193, server: ------.com
2012/09/11 13:14:42 [debug] 23649#0: *9 http finalize request: 400, "?" a:1, c:1
2012/09/11 13:14:42 [debug] 23649#0: *9 http terminate request count:1
2012/09/11 13:14:42 [debug] 23649#0: *9 http terminate cleanup count:1 blk:0
2012/09/11 13:14:42 [debug] 23649#0: *9 http request count:1 blk:0
2012/09/11 13:14:42 [debug] 23649#0: *9 http close request
2012/09/11 13:14:42 [debug] 23649#0: *9 http log handler
2012/09/11 13:14:42 [debug] 23649#0: *9 free: 0000000002646D60, unused: 2332
2012/09/11 13:14:42 [debug] 23649#0: *9 close http connection: 15
2012/09/11 13:14:42 [debug] 23649#0: *9 SSL_shutdown: 1
2012/09/11 13:14:42 [debug] 23649#0: *9 event timer del: 15: 1347369341415
2012/09/11 13:14:42 [debug] 23649#0: *9 reusable connection: 0
2012/09/11 13:14:42 [debug] 23649#0: *9 free: 0000000002646950
2012/09/11 13:14:42 [debug] 23649#0: *9 free: 00000000025A9CA0
2012/09/11 13:14:42 [debug] 23649#0: *9 free: 00000000025E4B90, unused: 8
2012/09/11 13:14:42 [debug] 23649#0: *9 free: 00000000025E4CA0, unused: 72
09-11-2012 06:13 AM - edited 09-11-2012 06:14 AM
Extremely late reply, but we are having this same issue, and it's intermittent, and has been going on for about 9 months. About 99% of our DPM responses work fine, but the others break with a failed SSL handshake. I'm wondering if it's something to do with DH params or cipher set, as we changed those in response to the DH LogJam attack.
Relevant log entry:
2016/08/20 22:22:48 [debug] 23249#0: *570479 event timer add: 9: 60000:1471731828712 2016/08/20 22:22:48 [debug] 23249#0: *570479 epoll add event: fd:9 op:1 ev:80000001 2016/08/20 22:22:48 [debug] 23249#0: *570479 post event 000000000120C290 2016/08/20 22:22:48 [debug] 23249#0: *570479 delete posted event 000000000120C290 2016/08/20 22:22:48 [debug] 23249#0: *570479 malloc: 000000000136C590:1296 2016/08/20 22:22:48 [debug] 23249#0: *570479 posix_memalign: 000000000118DCF0:256 @16 2016/08/20 22:22:48 [debug] 23249#0: *570479 malloc: 00000000011E07F0:1024 2016/08/20 22:22:48 [debug] 23249#0: *570479 posix_memalign: 0000000001190BC0:4096 @16 2016/08/20 22:22:48 [debug] 23249#0: *570479 http check ssl handshake 2016/08/20 22:22:48 [debug] 23249#0: *570479 https ssl handshake: 0x16 2016/08/20 22:22:48 [debug] 23249#0: *570479 SSL server name: "www.redacted.com" 2016/08/20 22:22:48 [debug] 23249#0: *570479 SSL_do_handshake: -1 2016/08/20 22:22:48 [debug] 23249#0: *570479 SSL_get_error: 2 2016/08/20 22:22:48 [debug] 23249#0: *570479 post event 000000000120C290 2016/08/20 22:22:48 [debug] 23249#0: *570479 delete posted event 000000000120C290 2016/08/20 22:22:48 [debug] 23249#0: *570479 SSL handshake handler: 0 2016/08/20 22:22:48 [debug] 23249#0: *570479 SSL_do_handshake: 0 2016/08/20 22:22:48 [debug] 23249#0: *570479 SSL_get_error: 5 2016/08/20 22:22:48 [info] 23249#0: *570479 peer closed connection in SSL handshake while SSL handshaking, client: xxx.xxx.xxx.xxx, server: www.redacted.com 2016/08/20 22:22:48 [debug] 23249#0: *570479 http request count:1 blk:0 2016/08/20 22:22:48 [debug] 23249#0: *570479 http close request 2016/08/20 22:22:48 [debug] 23249#0: *570479 http log handler 2016/08/20 22:22:48 [debug] 23249#0: *570479 free: 0000000001190BC0, unused: 2142 2016/08/20 22:22:48 [debug] 23249#0: *570479 close http connection: 9 2016/08/20 22:22:48 [debug] 23249#0: *570479 SSL_shutdown: 1 2016/08/20 22:22:48 [debug] 23249#0: *570479 event timer del: 9: 1471731828712 2016/08/20 22:22:48 [debug] 23249#0: *570479 reusable connection: 0 2016/08/20 22:22:48 [debug] 23249#0: *570479 free: 00000000011E07F0 2016/08/20 22:22:48 [debug] 23249#0: *570479 free: 000000000136C590 2016/08/20 22:22:48 [debug] 23249#0: *570479 free: 00000000012DAB20, unused: 8 2016/08/20 22:22:48 [debug] 23249#0: *570479 free: 000000000118DCF0, unused: 72
Our SSL config is:
ssl_protocols TLSv1.1 TLSv1.2; ssl_ciphers 'ECDHE-RSA-AES128-GCM-SHA256:ECDHE-ECDSA-AES128-GCM-SHA256:ECDHE-RSA-AES256-GCM-SHA384:ECDHE-ECDSA-AES256-GCM-SHA384:DHE-RSA-AES128-GCM-SHA256:DHE-DSS-AES128-GCM-SHA256:kEDH+AESGCM:ECDHE-RSA-AES128-SHA256:ECDHE-ECDSA-AES128-SHA256:ECDHE-RSA-AES128-SHA:ECDHE-ECDSA-AES128-SHA:ECDHE-RSA-AES256-SHA384:ECDHE-ECDSA-AES256-SHA384:ECDHE-RSA-AES256-SHA:ECDHE-ECDSA-AES256-SHA:DHE-RSA-AES128-SHA256:DHE-RSA-AES128-SHA:DHE-DSS-AES128-SHA256:DHE-RSA-AES256-SHA256:DHE-DSS-AES256-SHA:DHE-RSA-AES256-SHA:AES128-GCM-SHA256:AES256-GCM-SHA384:AES128-SHA256:AES256-SHA256:AES128-SHA:AES256-SHA:AES:CAMELLIA:DES-CBC3-SHA:!aNULL:!eNULL:!EXPORT:!DES:!RC4:!MD5:!PSK:!aECDH:!EDH-DSS-DES-CBC3-SHA:!EDH-RSA-DES-CBC3-SHA:!KRB5-DES-CBC3-SHA'; ssl_prefer_server_ciphers on; ssl_dhparam /etc/ssl/dhparams.pem;
Which is recommended by the NGINX section on this page.
All of these requests originate from the same IP at Authorize.NET, but it's like it's shared across a bunch of internal machines at Authorize.NET and one of them doesn't support the cipher set we are using, but the others do? So most of the time it works, but when the incompatible machine makes the callback the handshake fails?
I'm pretty much out of ideas on how to handle this on our end, as we are passing the Qualys SSL scanner with an A grade, as well as all of our PCI scans, and we also don't have any complaints from users, so this issue seems to be totally localized to these DPM callbacks. Any thoughts or suggestions would be greatly appreciated...
08-22-2016 02:51 PM