logs generated by SSLVPN connections?

[Jay_Libove]

Not sure if this should go in Log & Report or here in VPN. It' s about logs, generated by SSLVPN connections. I don' t understand why a certain log entry (one extra new connection after closing an SSL VPN tunnel) is created by activity on my SSLVPN. (FortiOS 5.0.4). And although I do generally understand the rest (web portal then actual SSL VPN tunnel), I worry whether these two evidently related connections arriving to my FortiGate on two different public IP interfaces could cause a problem. Below is a sample of the log entries created as a result of one client making one SSLVPN login, browsing a couple of websites, then closing the connection, all within about three minutes. Here' s some data: * The client' s IP is 88.26.220.104 * The FortiGate' s two ISP interfacess are- ** ISP-Colt on 62.97.102.90 ** ONO on 84.124.127.14 Log entries: dstip=84.124.127.14, and also dstip=62.97.102.90 [these are the two public interfaces of our FG100D, " ISP-Colt" and " ONO" . The FortiClient SSLVPN client connects to the DNS name fgsslvpn.socialpoint.es, which resolves to both of those IP addresses. DNS gives round-robin responses, first one then the other IP, then back again, etc. Here are the traffic and vpn log entries for the SSLVPN session, commented: # It all starts with a connection from the client [88.26.220.104] to the FortiGate' s ONO public interface: Dec 3 15:58:17 192.168.1.4 date=2013-12-03 time=15:58:16 devname=FG100D3G13807731 devid=FG100D3G13807731 logid=0001000014 type=traffic subtype=local level=notice vd=root srcip=88.26.220.104 srcport=49645 srcintf=" ONO" dstip=84.124.127.14 dstport=8443 dstintf=" root" sessionid=85401283 status=close policyid=0 dstcountry=" Spain" srccountry=" Spain" trandisp=noop service=8443/tcp proto=6 app=" SSLVPN" duration=2 sentbyte=120 rcvdbyte=132 sentpkt=3 rcvdpkt=3 # Then we get the first pair of " SSL new connection" and " SSL tunnel established" messages. # tunneltype=ssl Dec 3 15:58:20 192.168.1.4 date=2013-12-03 time=15:58:20 devname=FG100D3G13807731 devid=FG100D3G13807731 logid=0101039943 type=event subtype=vpn level=information vd=" root" action=" ssl-new-con" tunneltype=" ssl" tunnel_id=0 remote_ip=88.26.220.104 tunnel_ip=(null) user=" N/A" group=" N/A" dst_host=" N/A" reason=" N/A" msg=" SSL new connection" # tunneltype=ssl-web Dec 3 15:58:20 192.168.1.4 date=2013-12-03 time=15:58:20 devname=FG100D3G13807731 devid=FG100D3G13807731 logid=0101039424 type=event subtype=vpn level=information vd=" root" action=" tunnel-up" tunneltype=" ssl-web" tunnel_id=796469213 remote_ip=88.26.220.104 tunnel_ip=(null) user=" jlibove" group=" sslvpntunnelandportal" dst_host=" N/A" reason=" login successfully" msg=" SSL tunnel established" # .. and the second pair, about one second later. # tunneltype=ssl Dec 3 15:58:21 192.168.1.4 date=2013-12-03 time=15:58:21 devname=FG100D3G13807731 devid=FG100D3G13807731 logid=0101039943 type=event subtype=vpn level=information vd=" root" action=" ssl-new-con" tunneltype=" ssl" tunnel_id=0 remote_ip=88.26.220.104 tunnel_ip=(null) user=" N/A" group=" N/A" dst_host=" N/A" reason=" N/A" msg=" SSL new connection" # tunneltype=ssl-tunnel Dec 3 15:58:22 192.168.1.4 date=2013-12-03 time=15:58:22 devname=FG100D3G13807731 devid=FG100D3G13807731 logid=0101039947 type=event subtype=vpn level=information vd=" root" action=" tunnel-up" tunneltype=" ssl-tunnel" tunnel_id=796469214 remote_ip=88.26.220.104 tunnel_ip=192.168.8.69 user=" jlibove" group=" sslvpntunnelandportal" dst_host=" N/A" reason=" N/A" msg=" SSL tunnel established" # These two pairs of log entries above don' t give us the public interface of the FG on which the connections occurred. # But we do have two different tunnel IDs, 796469213 and 796469213, between the two otherwise idential log entries one second apart. # Looking at the tunneltypes (of which we see *three* distinct values), I guess we' re seeing a connection from the FortiClient to the SSL WEB portal # before it then sets up the real SSL VPN tunnel. # Then we get a pair of session close messages from the FG, almost identical to each other, a few seconds apart, # the first mentioning the ISP-Colt interface, and the second metioning the ONO interface. # What session is there to close? Why is the ISP-Colt interface involved at all, since it was the " ONO" interface involved above? Dec 3 15:58:38 192.168.1.4 date=2013-12-03 time=15:58:38 devname=FG100D3G13807731 devid=FG100D3G13807731 logid=0001000014 type=traffic subtype=local level=notice vd=root srcip=88.26.220.104 srcport=49646 srcintf=" ISP-Colt" dstip=62.97.102.90 dstport=8443 dstintf=" root" sessionid=85401621 status=close policyid=0 dstcountry=" Spain" srccountry=" Spain" trandisp=noop service=8443/tcp proto=6 app=" SSLVPN" duration=18 sentbyte=3225 rcvdbyte=24285 sentpkt=18 rcvdpkt=28 Dec 3 15:59:48 192.168.1.4 date=2013-12-03 time=15:59:47 devname=FG100D3G13807731 devid=FG100D3G13807731 logid=0001000014 type=traffic subtype=local level=notice vd=root srcip=88.26.220.104 srcport=49627 srcintf=" ONO" dstip=84.124.127.14 dstport=8443 dstintf=" root" sessionid=85389258 status=close policyid=0 dstcountry=" Spain" srccountry=" Spain" trandisp=noop service=8443/tcp proto=6 app=" SSLVPN" duration=308 sentbyte=2930 rcvdbyte=21785 sentpkt=17 rcvdpkt=30 # Then the user closes the connection, and we get: # Two tunnel downs, one for ssl-tunnel and the other for ssl-web Dec 3 16:00:18 192.168.1.4 date=2013-12-03 time=16:00:18 devname=FG100D3G13807731 devid=FG100D3G13807731 logid=0101039948 type=event subtype=vpn level=information vd=" root" action=" tunnel-down" tunneltype=" ssl-tunnel" tunnel_id=796469214 remote_ip=88.26.220.104 tunnel_ip=192.168.8.69 user=" jlibove" group=" sslvpntunnelandportal" dst_host=" N/A" reason=" N/A" duration=116 sent=1703693 rcvd=159463 msg=" SSL tunnel shutdown" Dec 3 16:00:18 192.168.1.4 date=2013-12-03 time=16:00:18 devname=FG100D3G13807731 devid=FG100D3G13807731 logid=0101039425 type=event subtype=vpn level=information vd=" root" action=" tunnel-down" tunneltype=" ssl-web" tunnel_id=796469213 remote_ip=88.26.220.104 tunnel_ip=(null) user=" jlibove" group=" sslvpntunnelandportal" dst_host=" N/A" reason=" N/A" duration=118 sent=0 rcvd=0 msg=" SSL tunnel shutdown" # Then, for some strange reason, we get a ssl-new-con. Why? Dec 3 16:00:21 192.168.1.4 date=2013-12-03 time=16:00:21 devname=FG100D3G13807731 devid=FG100D3G13807731 logid=0101039943 type=event subtype=vpn level=information vd=" root" action=" ssl-new-con" tunneltype=" ssl" tunnel_id=0 remote_ip=88.26.220.104 tunnel_ip=(null) user=" N/A" group=" N/A" dst_host=" N/A" reason=" N/A" msg=" SSL new connection" # And finally, a pair of close which I guess are the TCP circuit closes for the SSL tunnel connections. Dec 3 16:00:29 192.168.1.4 date=2013-12-03 time=16:00:29 devname=FG100D3G13807731 devid=FG100D3G13807731 logid=0001000014 type=traffic subtype=local level=notice vd=root srcip=88.26.220.104 srcport=49647 srcintf=" ISP-Colt" dstip=62.97.102.90 dstport=8443 dstintf=" root" sessionid=85401657 status=close policyid=0 dstcountry=" Spain" srccountry=" Spain" trandisp=noop service=8443/tcp proto=6 app=" SSLVPN" duration=128 sentbyte=282256 rcvdbyte=1853880 sentpkt=1955 rcvdpkt=2066 Dec 3 16:00:34 192.168.1.4 date=2013-12-03 time=16:00:34 devname=FG100D3G13807731 devid=FG100D3G13807731 logid=0001000014 type=traffic subtype=local level=notice vd=root srcip=88.26.220.104 srcport=49726 srcintf=" ONO" dstip=84.124.127.14 dstport=8443 dstintf=" root" sessionid=85408118 status=close policyid=0 dstcountry=" Spain" srccountry=" Spain" trandisp=noop service=8443/tcp proto=6 app=" SSLVPN" duration=12 sentbyte=1275 rcvdbyte=1215 sentpkt=7 rcvdpkt=5 So, I guess the above makes sense, given FortiGate' s use of a connection to a web portal in order to initiate the real SSL VPN tunnel. (Although I' d have preferred it be simpler - an SSLVPN tunnel simply being like an OpenVPN single TCP circuit). And I can see why these two connections might happen across both of the two public interfaces of the FortiGate, due to round robin responses to the DNS query for the one public name we' ve published. So my question devolves to: Is it likely to cause any kind of problem that the FortiGate gets the SSL web portal connection on one public IP and the actual SSLN VPN connection on another public IP? Will it get confused, time out, close connections, cause any other kind of problem? thanks, Jay

[oheigl]

Well I rather believe that this is a weird behavior from the FortiGate, and the client is not connection to both IPs. Can you check with the packet sniffer, on which interfaces you can see the packets from the client? Because the domain is looked up once and then it' s in the clients dns cache, so if th connection happens seconds after that, I guess it will not make another lookup. Just figure it out with a packet trace, and confirm this. My guess is that the logging feature is a little bit buggy with your configuration