Displaying #traffic-server/2015-12-21.log:

Mon Dec 21 01:01:55 2015  biilmann:Joined the channel
Mon Dec 21 02:48:55 2015  psp1:Joined the channel
Mon Dec 21 03:02:53 2015  es:Joined the channel
Mon Dec 21 04:57:50 2015  biilmann:Joined the channel
Mon Dec 21 05:41:47 2015  biilmann:Joined the channel
Mon Dec 21 06:55:36 2015  slx86:Joined the channel
Mon Dec 21 07:03:11 2015  psp:Joined the channel
Mon Dec 21 09:17:37 2015  Lethalman:Joined the channel
Mon Dec 21 09:23:27 2015  lrea:Joined the channel
Mon Dec 21 09:44:57 2015  luc__:Joined the channel
Mon Dec 21 09:48:16 2015  Teitoku:Joined the channel
Mon Dec 21 09:48:25 2015  frantz_:Joined the channel
Mon Dec 21 09:48:40 2015  ask-:Joined the channel
Mon Dec 21 09:56:14 2015  briang_:Joined the channel
Mon Dec 21 09:56:15 2015  briang_:Joined the channel
Mon Dec 21 10:02:59 2015  Zerpex:Joined the channel
Mon Dec 21 10:03:50 2015  jpeach_:Joined the channel
Mon Dec 21 10:04:00 2015  frank--:Joined the channel
Mon Dec 21 10:12:27 2015  mturk:Joined the channel
Mon Dec 21 10:12:28 2015  mturk:Joined the channel
Mon Dec 21 10:14:10 2015  Lethalman:Joined the channel
Mon Dec 21 11:25:07 2015  mturk:Joined the channel
Mon Dec 21 11:25:07 2015  mturk:Joined the channel
Mon Dec 21 12:55:13 2015  niq:Joined the channel
Mon Dec 21 13:14:33 2015  shinrich1:Joined the channel
Mon Dec 21 13:16:17 2015  shinrich2:Joined the channel
Mon Dec 21 14:13:10 2015  yamc:Joined the channel
Mon Dec 21 14:17:52 2015  yamc:Joined the channel
Mon Dec 21 14:28:30 2015  lev__:Hi guys, if you could take a look on this one: https://issues.apache.org/jira/browse/TS-4093 ATS crashes inside ssl_callback_info
Mon Dec 21 14:28:40 2015  lev__:I have it now in gdb
Mon Dec 21 14:29:58 2015  shinrich1:Joined the channel
Mon Dec 21 15:09:29 2015  JSeymour:Joined the channel
Mon Dec 21 15:09:29 2015  rokubo:Joined the channel
Mon Dec 21 15:09:29 2015  shinya:Joined the channel
Mon Dec 21 15:09:29 2015  akotani:Joined the channel
Mon Dec 21 15:33:54 2015  yamc:I think most people are gone for the holidays. I'm not that familiar with that section of code but netvc == 0 seems wrong.
Mon Dec 21 15:34:09 2015  yamc:This is 6.0.1 or 6.1?
Mon Dec 21 15:37:17 2015  lev__:5.3.2
Mon Dec 21 15:43:27 2015  lrea:Left the channel
Mon Dec 21 15:46:33 2015  esproul:Joined the channel
Mon Dec 21 15:46:44 2015  yamc:Do you have any SSL hooks set, in particular the SSL_PRE_ACCEPT hook?
Mon Dec 21 15:51:21 2015  shinrich1:lev__: do you see the crash all the time? Or only occaisionally?
Mon Dec 21 15:53:28 2015  lev__:shinrich1: I run ATS on a machine with strongSwan/openvpn and crash is reproducible every time when win10 client connected. Does not happen with linux clients
Mon Dec 21 15:54:17 2015  lev__:yamc: I do have TS_SSL_CERT_HOOK
Mon Dec 21 15:54:36 2015  yamc:Does it touch the SSL instance object associated with the cert?
Mon Dec 21 15:54:54 2015  yamc:The root cause seems to be the SSL app data is getting reset to NULL when ATS expects it to be the netvc pointer.
Mon Dec 21 15:56:05 2015  shinrich1:lev__: is the vpn client connected to the ATS process? Or do they both just happen to be running on the same machine?
Mon Dec 21 15:57:05 2015  lev__:shinrich1: VPN client is on another machine, on machine with ATS I have VPN server
Mon Dec 21 15:58:11 2015  shinrich1:So the connection emerging from the vpn tunnel is a SSL connection which gets processed by ATS?
Mon Dec 21 15:58:53 2015  lev__:shinrich1: yep
Mon Dec 21 15:59:46 2015  lev__:https://gist.github.com/stipa/e0c0057e5e3135020194 second line, 198.xx is an IP address inside VPN
Mon Dec 21 16:00:13 2015  shinrich1:Does your TS_SSL_CERT_HOOK directly manipulate the SSL object?
Mon Dec 21 16:00:33 2015  jumby:Joined the channel
Mon Dec 21 16:01:04 2015  shinrich1:Sounds like we should be able to reproduce the environment anyway, once I'm back in the home office this afternoon.
Mon Dec 21 16:01:05 2015  lev__:shinrich1: I calls SSL_get_servername
Mon Dec 21 16:01:11 2015  lev__:it
Mon Dec 21 16:01:43 2015  shinrich1:That sounds safe enough. I'll try reproducing this afternoon.
Mon Dec 21 16:03:24 2015  lev__:shinrich1: please note that it miracuolusly happens with connection initiated by windows 10 only. I wonder why.
Mon Dec 21 16:04:27 2015  shinrich1:Yes, that is very mysterious..
Mon Dec 21 16:07:10 2015  lev__:anything useful I could get from logs/gdb ?
Mon Dec 21 16:10:21 2015  shinrich1:I'm assuming that the ssl object in frame 0, is the same as the this->ssl in frame 4
Mon Dec 21 16:11:22 2015  yamc:Are you willing to tweak the code and try that?
Mon Dec 21 16:12:05 2015  shinrich1:If it happens every single time, you could play with data breakpoints (watches) to understand app_data gets cleared for a given ssl object, but that likely requires having your own openssl compiled.
Mon Dec 21 16:12:11 2015  yamc:He could put code in just before calling SSLAccept that logs if the ssl app data is null and resets it to the netvc
Mon Dec 21 16:12:45 2015  shinrich1:Yes, that would be interesting. Still wouldn't tell us who is doing the clearing through.
Mon Dec 21 16:16:04 2015  yamc:But we'd know that was really the problem, rather than a surmise.
Mon Dec 21 16:20:04 2015  lev__:yeah I can put a breakpoint before SSLAccept
Mon Dec 21 16:22:36 2015  lev__:interesting that it crashes right after VPN client got connected. After I restarter ATS both client and ATS work just fine
Mon Dec 21 16:24:22 2015  shinrich1:Maybe the first SSL connection through the VPN aborts quickly or shuts down strangely?
Mon Dec 21 16:24:23 2015  lev__:I wonder if I could somehow isolate that SSL packet
Mon Dec 21 16:32:25 2015  lev__:this is what *ssl contains at the moment of segfault https://gist.github.com/stipa/7b932ec93ab11869dc63
Mon Dec 21 16:38:28 2015  shinrich1:Ok, ssl->ex_data is the issue. ssl->ex_data.sk should not be null if we had previously called SSL_set_ex_data in make_ssl_connection. So either that call wasn't made (don't see how that could happen) or something cleared that value.
Mon Dec 21 16:44:03 2015  lev__:shinrich1: I put a watch on ssl->ex_data and found a place where it is set to 0
Mon Dec 21 16:44:56 2015  yamc:Which is...?
Mon Dec 21 16:44:58 2015  lev__:shinrich1: https://gist.github.com/stipa/c799510810efefc4a007
Mon Dec 21 16:46:44 2015  lev__:in my callback I call TSVConnClose(sslVc), hm..
Mon Dec 21 16:49:01 2015  lev__:wondering if this could be the problem
Mon Dec 21 16:52:46 2015  blattj:Joined the channel
Mon Dec 21 16:56:58 2015  niq:Joined the channel
Mon Dec 21 16:57:44 2015  niq:Joined the channel
Mon Dec 21 17:14:50 2015  lev__:yep, that was the cause. Lesson learned: no TSVConnClose calls on TS_SSL_CERT_HOOK
Mon Dec 21 17:17:03 2015  jpeach:lev__: are you trying to abort the ssl session?
Mon Dec 21 17:17:24 2015  lev__:jpeach: yep
Mon Dec 21 17:19:53 2015  shinrich1:Joined the channel
Mon Dec 21 17:36:38 2015  yamc:You should be able to abort in the PRE_ACCEPT hook.
Mon Dec 21 17:36:47 2015  yamc:Or is that too late because you don't have SNI at that point?
Mon Dec 21 17:37:06 2015  lev__:yamc: exactly
Mon Dec 21 17:37:40 2015  yamc:Hmmm. We should look at how to handle that.
Mon Dec 21 17:38:10 2015  yamc:It'd be a bit ugly, the close would need to be deferred until after the accept is finished.
Mon Dec 21 17:38:21 2015  lev__:I think my business logic does not force me to abort it at that place, so for me problem is kinda solved
Mon Dec 21 17:38:44 2015  yamc:At this point, file or update your bug to say that a plugin shoudl be able to arrange for hte connection to close in the CERT hook.
Mon Dec 21 17:39:10 2015  yamc:Not sure when any one will ahve time to fix that, so having a work around is good for you.
Mon Dec 21 17:41:11 2015  lev__:yamc: updated JIRA case. Yep I also call close in the thread which is executed after TS_SSL_CERT_HOOK is finished
Mon Dec 21 17:49:25 2015  mturk:Joined the channel
Mon Dec 21 17:49:26 2015  mturk:Joined the channel
Mon Dec 21 18:18:29 2015  niq:Joined the channel
Mon Dec 21 18:19:24 2015  shinrich1:Joined the channel
Mon Dec 21 18:42:18 2015  es:Joined the channel
Mon Dec 21 18:44:34 2015  es1:Joined the channel
Mon Dec 21 18:44:59 2015  es1:Joined the channel
Mon Dec 21 18:45:34 2015  shinrich1:Joined the channel
Mon Dec 21 18:45:39 2015  biilmann:Joined the channel
Mon Dec 21 18:49:58 2015  shinrich1:Joined the channel
Mon Dec 21 18:51:44 2015  shinrich2:Joined the channel
Mon Dec 21 19:16:00 2015  psp:Joined the channel
Mon Dec 21 19:17:46 2015  psp1:Joined the channel
Mon Dec 21 19:37:42 2015  zwoop:yamc I merge TS-4091 as well to 6.1.x, any concerns ?
Mon Dec 21 19:44:34 2015  zwoop:I take that as "yes"
Mon Dec 21 19:44:37 2015  zwoop:or no
Mon Dec 21 20:00:03 2015  biilmann:Joined the channel
Mon Dec 21 20:01:43 2015  niq:Joined the channel
Mon Dec 21 20:01:56 2015  niq:Joined the channel
Mon Dec 21 20:36:58 2015  es:Joined the channel
Mon Dec 21 20:56:08 2015  oag:Joined the channel
Mon Dec 21 21:06:16 2015  danielxu:Joined the channel
Mon Dec 21 21:11:21 2015  danielxu:Joined the channel
Mon Dec 21 21:16:23 2015  danielxu:Joined the channel
Mon Dec 21 21:21:26 2015  danielxu:Joined the channel
Mon Dec 21 21:26:34 2015  danielxu:Joined the channel
Mon Dec 21 21:31:34 2015  danielxu:Joined the channel
Mon Dec 21 21:36:33 2015  danielxu:Joined the channel
Mon Dec 21 21:41:33 2015  danielxu:Joined the channel
Mon Dec 21 21:44:19 2015  biilmann:Joined the channel
Mon Dec 21 21:47:36 2015  danielxu:Joined the channel
Mon Dec 21 21:54:00 2015  biilmann:Joined the channel
Mon Dec 21 22:05:11 2015  danielxu:Joined the channel
Mon Dec 21 23:14:37 2015  shinrich1:Joined the channel
Mon Dec 21 23:38:22 2015  danielxu:Joined the channel
Mon Dec 21 23:43:45 2015  danielxu:Joined the channel
Mon Dec 21 23:45:45 2015  biilmann:Joined the channel
Mon Dec 21 23:53:43 2015  danielxu:Joined the channel
Mon Dec 21 23:54:50 2015  shinrich1:Joined the channel

Comments