flightaware / piaware

Client-side package and programs for forwarding ADS-B data to FlightAware
BSD 2-Clause "Simplified" License
493 stars 70 forks source link

piaware keeps reconnecting #33

Closed anish closed 8 years ago

anish commented 8 years ago

With update to 3.0.2, piaware keeps disconnecting from the fa server every minute or so, no communication visible on the stats web page at all. Was working fine before the update from 2.1.5

Aug 02 01:21:03 inktomi piaware[28036]: piaware version 3.0.2 is running, process ID 28036
Aug 02 01:21:03 inktomi piaware[28036]: your system info is: Linux inktomi 4.1.18-2-ARCH #1 Thu Feb 25 19:27:02 MST 2016 armv6l GNU/Linux
Aug 02 01:21:05 inktomi piaware[28036]: Connecting to FlightAware adept server at piaware.flightaware.com/1200
Aug 02 01:21:05 inktomi piaware[28036]: Connection with adept server at piaware.flightaware.com/1200 established
Aug 02 01:21:06 inktomi piaware[28036]: FlightAware server SSL certificate validated
Aug 02 01:21:06 inktomi piaware[28036]: encrypted session established with FlightAware
Aug 02 01:21:08 inktomi piaware[28036]: ADS-B data program 'dump1090' is listening on port 30005, so far so good
Aug 02 01:21:08 inktomi piaware[28036]: Starting faup1090: /usr/lib/piaware/helpers/faup1090 --net-bo-ipaddr localhost --net-bo-port 30005 --stdout
Aug 02 01:21:08 inktomi piaware[28036]: Started faup1090 (pid 28065) to connect to dump1090
Aug 02 01:21:09 inktomi piaware[28036]: Lost connection to adept server at piaware.flightaware.com/1200: server closed connection
Aug 02 01:21:09 inktomi piaware[28036]: reconnecting in 54 seconds...
Aug 02 01:21:10 inktomi piaware[28036]: piaware received a message from dump1090!
Aug 02 01:21:39 inktomi piaware[28036]: 1 msgs recv'd from dump1090; 0 msgs sent to FlightAware
Aug 02 01:22:03 inktomi piaware[28036]: Connecting to FlightAware adept server at piaware.flightaware.com/1200
Aug 02 01:22:03 inktomi piaware[28036]: Connection with adept server at piaware.flightaware.com/1200 established
Aug 02 01:22:04 inktomi piaware[28036]: FlightAware server SSL certificate validated
Aug 02 01:22:04 inktomi piaware[28036]: encrypted session established with FlightAware
Aug 02 01:22:05 inktomi piaware[28036]: Lost connection to adept server at piaware.flightaware.com/1200: server closed connection
Aug 02 01:22:05 inktomi piaware[28036]: reconnecting in 54 seconds...
Aug 02 01:22:59 inktomi piaware[28036]: Connecting to FlightAware adept server at 70.42.6.197/1200
Aug 02 01:22:59 inktomi piaware[28036]: Connection with adept server at 70.42.6.197/1200 established
Aug 02 01:22:59 inktomi piaware[28036]: FlightAware server SSL certificate validated
Aug 02 01:22:59 inktomi piaware[28036]: encrypted session established with FlightAware
Aug 02 01:23:00 inktomi piaware[28036]: Lost connection to adept server at 70.42.6.197/1200: server closed connection
Aug 02 01:23:00 inktomi piaware[28036]: reconnecting in 56 seconds...
Aug 02 01:23:56 inktomi piaware[28036]: Connecting to FlightAware adept server at 70.42.6.198/1200
Aug 02 01:23:56 inktomi piaware[28036]: Connection with adept server at 70.42.6.198/1200 established
Aug 02 01:23:57 inktomi piaware[28036]: FlightAware server SSL certificate validated
Aug 02 01:23:57 inktomi piaware[28036]: encrypted session established with FlightAware
Aug 02 01:23:58 inktomi piaware[28036]: Lost connection to adept server at 70.42.6.198/1200: server closed connection
Aug 02 01:23:58 inktomi piaware[28036]: reconnecting in 53 seconds...
Aug 02 01:24:51 inktomi piaware[28036]: Connecting to FlightAware adept server at 70.42.6.191/1200
Aug 02 01:24:51 inktomi piaware[28036]: Connection with adept server at 70.42.6.191/1200 established
Aug 02 01:24:52 inktomi piaware[28036]: FlightAware server SSL certificate validated
Aug 02 01:24:52 inktomi piaware[28036]: encrypted session established with FlightAware
Aug 02 01:24:52 inktomi piaware[28036]: Lost connection to adept server at 70.42.6.191/1200: server closed connection
Aug 02 01:24:52 inktomi piaware[28036]: reconnecting in 64 seconds...
Aug 02 01:25:56 inktomi piaware[28036]: Connecting to FlightAware adept server at piaware.flightaware.com/1200
Aug 02 01:25:57 inktomi piaware[28036]: Connection with adept server at piaware.flightaware.com/1200 established
Aug 02 01:25:57 inktomi piaware[28036]: FlightAware server SSL certificate validated
Aug 02 01:25:57 inktomi piaware[28036]: encrypted session established with FlightAware
Aug 02 01:25:58 inktomi piaware[28036]: Lost connection to adept server at piaware.flightaware.com/1200: server closed connection
Aug 02 01:25:58 inktomi piaware[28036]: reconnecting in 61 seconds...
Aug 02 01:26:39 inktomi piaware[28036]: 2 msgs recv'd from dump1090 (1 in last 5m); 0 msgs sent to FlightAware
Aug 02 01:26:59 inktomi piaware[28036]: Connecting to FlightAware adept server at piaware.flightaware.com/1200
Aug 02 01:27:00 inktomi piaware[28036]: Connection with adept server at piaware.flightaware.com/1200 established
Aug 02 01:27:00 inktomi piaware[28036]: FlightAware server SSL certificate validated
Aug 02 01:27:00 inktomi piaware[28036]: encrypted session established with FlightAware
Aug 02 01:27:01 inktomi piaware[28036]: Lost connection to adept server at piaware.flightaware.com/1200: server closed connection
Aug 02 01:27:01 inktomi piaware[28036]: reconnecting in 55 seconds...
Aug 02 01:27:56 inktomi piaware[28036]: Connecting to FlightAware adept server at 70.42.6.197/1200
Aug 02 01:27:56 inktomi piaware[28036]: Connection with adept server at 70.42.6.197/1200 established
Aug 02 01:27:57 inktomi piaware[28036]: FlightAware server SSL certificate validated
Aug 02 01:27:57 inktomi piaware[28036]: encrypted session established with FlightAware
Aug 02 01:27:58 inktomi piaware[28036]: Lost connection to adept server at 70.42.6.197/1200: server closed connection
Aug 02 01:27:58 inktomi piaware[28036]: reconnecting in 52 seconds...
Aug 02 01:28:50 inktomi piaware[28036]: Connecting to FlightAware adept server at 70.42.6.198/1200
Aug 02 01:28:50 inktomi piaware[28036]: Connection with adept server at 70.42.6.198/1200 established
Aug 02 01:28:50 inktomi piaware[28036]: FlightAware server SSL certificate validated
Aug 02 01:28:50 inktomi piaware[28036]: encrypted session established with FlightAware
Aug 02 01:28:51 inktomi piaware[28036]: Lost connection to adept server at 70.42.6.198/1200: server closed connection
Aug 02 01:28:51 inktomi piaware[28036]: reconnecting in 66 seconds...
Aug 02 01:29:57 inktomi piaware[28036]: Connecting to FlightAware adept server at 70.42.6.191/1200
Aug 02 01:29:58 inktomi piaware[28036]: Connection with adept server at 70.42.6.191/1200 established
Aug 02 01:29:58 inktomi piaware[28036]: FlightAware server SSL certificate validated
Aug 02 01:29:58 inktomi piaware[28036]: encrypted session established with FlightAware
Aug 02 01:29:59 inktomi piaware[28036]: Lost connection to adept server at 70.42.6.191/1200: server closed connection
Aug 02 01:29:59 inktomi piaware[28036]: reconnecting in 71 seconds...
mutability commented 8 years ago

Is this on arch? It sounds like a long-standing arch packaging bug as I see arch piaware logging in then disconnecting regularly. Can you research what's going on? I don't have an arch system to test on.

Note that there are 300+ flightfeeders running 3.0.3 that do not see this problem.

mutability commented 8 years ago

There is also a nonzero chance that you hit a maintenance window for the adept servers, for a while all but one server would have been accepting and dropping connections. Is it OK now?

mutability commented 8 years ago

I looked on the server side and there's nothing odd there, you just connect then immediately disconnect.

What tcl / tcltls versions are you using?

mutability commented 8 years ago

I also looked at a diff between 2.1-5 and 3.0.2 and there are no real changes to the connection/login process that I could see causing this. (Note that there are changes in 3.0.3, but you said it was with 3.0.2)

anish commented 8 years ago

I just compared the packaging on both sides, and while it is not exactly the same, I essentially ran the the entire post-install script for wheezy by hand, no difference. Here are the tcl versions :

local/tcl 8.6.4-1
    The Tcl scripting language
local/tcllauncher 1.5-2
    A launcher for Tcl applications
local/tcllib 1.18-1
    Set of pure-Tcl extensions.
local/tclx 8.4-4
    Provides OS primitives, file scanning, data records etc. for Tcl
local/tk 8.6.4-1
    A windowing toolkit for use with tcl
anish commented 8 years ago

Config if it helps :

[anish@inktomi ~]$ sudo piaware-config -showall
#adept-serverhosts             piaware.flightaware.com piaware.flightaware.com 70.42.6.197 70.42.6.198 70.42.6.191 # using default value
#adept-serverport              1200                           # using default value
#allow-auto-updates            no                             # using default value
#allow-manual-updates          no                             # using default value
allow-mlat                     yes                            # value set at /etc/piaware.conf:4
flightaware-password           <foo>                       # value set at /etc/piaware.conf:2
flightaware-user               <bar>                         # value set at /etc/piaware.conf:1
#http-proxy-host               <unset>                        # no value set and no default value
#http-proxy-password           <unset>                        # no value set and no default value
#http-proxy-port               <unset>                        # no value set and no default value
#http-proxy-user               <unset>                        # no value set and no default value
#image-type                    <unset>                        # no value set and no default value
#manage-config                 no                             # using default value
mlat-results                   yes                            # value set at /etc/piaware.conf:5
mlat-results-format            beast,connect,localhost:30104 basestation,listen,31003 # value set at /etc/piaware.conf:3
anish commented 8 years ago

@mutability is there a way to drop the dependency on tclx ? Was looking to see if any out of date packages would cause issues, tclx blocks the update to tcl 8.6.5 and hasn't been updated in forever.

mutability commented 8 years ago

Tclx should work fine with tcl 8.6? It's not an easy dependency to remove

anish commented 8 years ago

Fair enough, it seems to be failing to build right now, looking for a patch. It was just that it hasn't been updated since 2012

bovine commented 8 years ago

TclX is available from https://github.com/flightaware/tclx

lehenbauer commented 8 years ago

TclX hasn't needed much in the way of updates although it could probably use freshening up. It should work fine with Tcl 8.6.

anish commented 8 years ago

Yeah, tclx found in the arch repos seems to be pulling from sourceforce. Will put a request sources. That said, sounds unrelated to above issues, yes ?

mutability commented 8 years ago

What's your tcl-tls version?

anish commented 8 years ago

There is no separate tcl-tls on Archlinux. I've always assumed it is just included in tcl, since FA communication was working before.

anish commented 8 years ago

Tried running through all these servers just to be sure, no dice :

Name:   piaware.flightaware.com
Address: 70.42.6.225
Name:   piaware.flightaware.com
Address: 70.42.6.197
Name:   piaware.flightaware.com
Address: 70.42.6.198
Name:   piaware.flightaware.com
Address: 70.42.6.224
anish commented 8 years ago

Actually, this is probably what you asked for @mutability

Name            : tls
Version         : 1.6.7-2
Description     : OpenSSL extension to Tcl
Architecture    : armv6h
mutability commented 8 years ago

1.6.7 should be fine. Hrm. Can you try piaware 3.0.3 and see if it behaves any differently?

anish commented 8 years ago

Can do !

On Aug 2, 2016 09:14, "Oliver Jowett" notifications@github.com wrote:

1.6.7 should be fine. Hrm. Can you try piaware 3.0.3 and see if it behaves any differently?

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub https://github.com/flightaware/piaware/issues/33#issuecomment-236956335, or mute the thread https://github.com/notifications/unsubscribe-auth/AAF_NnmX85o2jNLq9afpHbwTRAYDG8iKks5qb2zpgaJpZM4JaXUK .

anish commented 8 years ago

@mutability No bueno

Aug 02 10:00:44 inktomi piaware[1670]: piaware version 3.0.3 is running, process ID 1670
Aug 02 10:00:44 inktomi piaware[1670]: your system info is: Linux inktomi 4.4.16-1-ARCH #1 Thu Jul 28 19:26:04 MDT 2016 armv6l GNU/Linux
Aug 02 10:00:45 inktomi piaware[1670]: Connecting to FlightAware adept server at 70.42.6.225/1200
Aug 02 10:00:45 inktomi piaware[1670]: Connection with adept server at 70.42.6.225/1200 established
Aug 02 10:00:46 inktomi piaware[1670]: TLS handshake with adept server at 70.42.6.225/1200 completed
Aug 02 10:00:47 inktomi piaware[1670]: FlightAware server certificate validated
Aug 02 10:00:47 inktomi piaware[1670]: encrypted session established with FlightAware
Aug 02 10:00:49 inktomi piaware[1670]: ADS-B data program 'dump1090' is listening on port 30005, so far so good
Aug 02 10:00:49 inktomi piaware[1670]: Starting faup1090: /usr/lib/piaware/helpers/faup1090 --net-bo-ipaddr localhost --net-bo-port 30005 --stdout
Aug 02 10:00:49 inktomi piaware[1670]: Started faup1090 (pid 1700) to connect to dump1090
Aug 02 10:00:49 inktomi piaware[1670]: Lost connection to adept server at 70.42.6.225/1200: server closed connection
Aug 02 10:00:49 inktomi piaware[1670]: reconnecting in 68 seconds...
mutability commented 8 years ago

Can I get remote access to your system? Or a tcpdump of the traffic. (pcap capture)

mutability commented 8 years ago

Or if you can try this script and see what it outputs: https://gist.github.com/mutability/95e068be1908a53196efd1d54f34cc01

anish commented 8 years ago

Script out :

connecting to piaware.flightaware.com 1200
connected, handshaking
tls_callback: info sockdbb140 handshake start {before/connect initialization}
tls_callback: info sockdbb140 connect loop {before/connect initialization}
tls_callback: info sockdbb140 connect loop {SSLv2/v3 write client hello A}
tls_callback: info sockdbb140 connect loop {unknown state}
tls_callback: verify sockdbb140 2 {sha1_hash B69ABB0BF41433F4E27434BF6628CE1EA1CAA704 subject {CN=FlightAware Root,OU=Operations,O=FlightAware LLC,L=Houston,ST=TX,C=US} issuer {CN=FlightAware Root,OU=Operations,O=FlightAware LLC,L=Houston,ST=TX,C=US} notBefore {Dec  9 16:50:04 2015 GMT} notAfter {Dec  4 16:50:04 2035 GMT} serial A9FE756D9E6B94B4} 0 {self signed certificate in certificate chain}
tls_callback: verify sockdbb140 2 {sha1_hash B69ABB0BF41433F4E27434BF6628CE1EA1CAA704 subject {CN=FlightAware Root,OU=Operations,O=FlightAware LLC,L=Houston,ST=TX,C=US} issuer {CN=FlightAware Root,OU=Operations,O=FlightAware LLC,L=Houston,ST=TX,C=US} notBefore {Dec  9 16:50:04 2015 GMT} notAfter {Dec  4 16:50:04 2035 GMT} serial A9FE756D9E6B94B4} 1 {}
tls_callback: verify sockdbb140 1 {sha1_hash D191B12012733E764CA27D5DFB88336499C9C7C1 subject {CN=FlightAware Intermediate,OU=Operations,O=FlightAware LLC,ST=TX,C=US} issuer {CN=FlightAware Root,OU=Operations,O=FlightAware LLC,L=Houston,ST=TX,C=US} notBefore {Dec  9 16:59:51 2015 GMT} notAfter {Dec  6 16:59:51 2025 GMT} serial 2048} 1 {}
tls_callback: verify sockdbb140 0 {sha1_hash ED69EEEF3FEE10E7DDD1BEC93C10EDCDF88989A1 subject {CN=*.flightaware.com,OU=Operations,O=FlightAware LLC,L=Houston,ST=Texas,C=US} issuer {CN=FlightAware Intermediate,OU=Operations,O=FlightAware LLC,ST=TX,C=US} notBefore {Dec 11 16:33:41 2015 GMT} notAfter {Dec 11 16:33:41 2019 GMT} serial 2049} 1 {}
tls_callback: info sockdbb140 connect loop {unknown state}
tls_callback: info sockdbb140 connect loop {unknown state}
tls_callback: info sockdbb140 connect loop {unknown state}
tls_callback: info sockdbb140 connect loop {unknown state}
tls_callback: info sockdbb140 connect loop {unknown state}
tls_callback: info sockdbb140 connect loop {unknown state}
tls_callback: info sockdbb140 connect loop {unknown state}
tls_callback: info sockdbb140 connect loop {unknown state}
tls_callback: info sockdbb140 connect loop {unknown state}
tls_callback: info sockdbb140 connect loop {unknown state}
tls_callback: info sockdbb140 handshake done {SSL negotiation finished successfully}
tls_callback: info sockdbb140 connect exit {SSL negotiation finished successfully}
sending login message: clock    1470159300      mac     00:00:00:00:00:00       type    login
waiting for data
Got a line: clock       1470159300      status  ok      type    login_response  user    stone4x4
anish commented 8 years ago

Pcap output : pcap.zip

mutability commented 8 years ago

It is quite weird that the script works OK but piaware does not.

In your tcpdump I see your piaware generating a couple of encrypted alerts, one of them is probably a close notify, I don't know what the other is. I don't see those in my own tcpdumps.

I wonder if it is CA related. I would expect to see more logging if that was the case though. Are you sure the FlightAware CA certs are getting installed in the right place and correctly hashed?

If it's not that then I will probably need remote access to diagnose it further.

anish commented 8 years ago

I'm wondering if the update simply hosed my account somehow. Any way I can verify the certs in the package ? I can give access, would prefer to give details over email though.

mutability commented 8 years ago

sure: oliver@mutability.co.uk

The server isn't actively doing anything to disconnect you, it's not even getting the login message, it just sees you disconnect after the handshake, so it's not account related.

anish commented 8 years ago

Sent

mutability commented 8 years ago

OK so this is a bit horrible, what is happening is:

So the failure path of the fork/exec needs to be tweaked, I'll have a look on that.

anish commented 8 years ago

@mutability Wow that is some gnarly stuff. Do you want me to keep the ngrok session open longer ?

mutability commented 8 years ago

Give me 15 mins and I'll test a fix there

anish commented 8 years ago

Can do. Btw, if I am remembering correctly when I first started packaging there was a patch and a PR for a lack of dpkg-query around 2.1

On Aug 2, 2016 12:04 PM, "Oliver Jowett" notifications@github.com wrote:

Give me 15 mins and I'll test a fix there

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub https://github.com/flightaware/piaware/issues/33#issuecomment-237009198, or mute the thread https://github.com/notifications/unsubscribe-auth/AAF_NjCkKfbSTL19jEQQlbUBE6kDwP6Tks5qb5TUgaJpZM4JaXUK .

mutability commented 8 years ago

It tolerates the lack of dpkg-query fine, it's just fallout from a rearrangement of how the fork/exec of child processes is done.

mutability commented 8 years ago

Ok, commited a fix to the dev branch, it's also in place on your Pi.

anish commented 8 years ago

Thanks a lot Oliver !

On Aug 2, 2016 12:26 PM, "Oliver Jowett" notifications@github.com wrote:

Ok, commited a fix to the dev branch, it's also in place on your Pi.

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub https://github.com/flightaware/piaware/issues/33#issuecomment-237015738, or mute the thread https://github.com/notifications/unsubscribe-auth/AAF_NqKyZKUv6mshf7CJY7Ux_V8hsuxFks5qb5n8gaJpZM4JaXUK .

anish commented 8 years ago

Much success !

Aug 02 12:27:57 inktomi piaware[4905]: piaware version 3.0.3 is running, process ID 4905
Aug 02 12:27:57 inktomi piaware[4905]: your system info is: Linux inktomi 4.4.16-1-ARCH #1 Thu Jul 28 19:26:04 MDT 2016 armv6l GNU/Linux
Aug 02 12:27:58 inktomi piaware[4905]: Connecting to FlightAware adept server at piaware.flightaware.com/1200
Aug 02 12:27:58 inktomi piaware[4905]: Connection with adept server at piaware.flightaware.com/1200 established
Aug 02 12:27:59 inktomi piaware[4905]: TLS handshake with adept server at piaware.flightaware.com/1200 completed
Aug 02 12:28:01 inktomi piaware[4905]: FlightAware server certificate validated
Aug 02 12:28:01 inktomi piaware[4905]: encrypted session established with FlightAware
Aug 02 12:28:03 inktomi piaware[4905]: ADS-B data program 'dump1090' is listening on port 30005, so far so good
Aug 02 12:28:03 inktomi piaware[4905]: Starting faup1090: /usr/lib/piaware/helpers/faup1090 --net-bo-ipaddr localhost --net-bo-port 30005 --stdout --lat 37.787
Aug 02 12:28:03 inktomi piaware[4905]: Started faup1090 (pid 4941) to connect to dump1090
Aug 02 12:28:03 inktomi piaware[4905]: logged in to FlightAware as user anish7
Aug 02 12:28:03 inktomi piaware[4905]: multilateration data requested
Aug 02 12:28:04 inktomi piaware[4905]: Starting multilateration client: /usr/lib/piaware/helpers/fa-mlat-client --input-connect localhost:30005 --input-type du
Aug 02 12:28:04 inktomi piaware[4905]: piaware received a message from dump1090!
Aug 02 12:28:08 inktomi piaware[4905]: mlat-client(4949): fa-mlat-client 0.2.5~dev starting up
Aug 02 12:28:08 inktomi piaware[4905]: mlat-client(4949): Using UDP transport to 70.42.6.198:7779
Aug 02 12:28:08 inktomi piaware[4905]: mlat-client(4949): Listening for Basestation-format results connection on port 31003
Aug 02 12:28:08 inktomi piaware[4905]: mlat-client(4949): Input connected to localhost:30005
Aug 02 12:28:09 inktomi piaware[4905]: mlat-client(4949): Beast-format results connection with localhost:30104: connection established
Aug 02 12:28:11 inktomi piaware[4905]: piaware has successfully sent several msgs to FlightAware!
lines 1-22/22 (END)
anish commented 8 years ago

@mutability Will you be pushing https://github.com/flightaware/piaware/commit/fc3582a8f88c524eb9f615ab9c0f56bae7f76f52 to master soon ?

mutability commented 8 years ago

At the point I do a new release it will go to master. This doesn't affect the standard build and you can build from dev or a hash for arch in the meantime

anish commented 8 years ago

Already doing that. Btw, I see this :

Aug 04 23:01:37 inktomi piaware[9930]: mlat-client(9959): Receiver status: connected
Aug 04 23:01:37 inktomi piaware[9930]: mlat-client(9959): Server status:   synchronized with 62 nearby receivers
Aug 04 23:01:37 inktomi piaware[9930]: mlat-client(9959): Receiver:   26.2 msg/s received        8.2 msg/s processed (31%)
Aug 04 23:01:37 inktomi piaware[9930]: mlat-client(9959): Server:      0.1 kB/s from server    0.0kB/s TCP to server     0.1kB/s UDP to server
Aug 04 23:01:37 inktomi piaware[9930]: mlat-client(9959): Results:  33.3 positions/minute
Aug 04 23:01:37 inktomi piaware[9930]: mlat-client(9959): Aircraft: 1 of 2 Mode S, 4 of 4 ADS-B used

But I still see Multilateration (MLAT): Receiver Not Supported on the flightaware stats page. Is that expected ?

anish commented 8 years ago

@mutability any idea ?

mutability commented 8 years ago

The mlat thing is just a display issue because the web stuff doesn't recognize the arch-based build so assumes it does not support mlat.