A slightly different failure mode today, Pilotaware-OGN stopped responding on port 80 at 04:22 this morning, but seems to still be working other than the web server, although messages on 50002 looked very different between before and after the restart. Oh and before the restart it had spawned ~100 instances of the PA_TxSBS1 thread!
pi@ognpaw:~ $ telnet localhost 80
Trying 127.0.0.1...
Connected to localhost.
Escape character is '^]'.
GET / HTTP/1.1
Host: ognpaw.unseen.org
[nothing]
pi@ognpaw:~ $ netcat localhost 50002
@@@ Welcome to procServ (procServ Process Server 2.6.0)
@@@ Child "./PilotAware-OGN.exe" started at: Sat Apr 13 11:17:09 2019
(08:31:20) MLAT-SRVR : STATUS 400CEE Latency=(08:31:19.202) latency=1 error=114
(PARSE-FAIL)HTTP_Server.Exec() ... Client from 10.10.10.8:48536
(PARSE-FAIL)HTTP_Server.Exec() ... Request for /
(08:31:21) MLAT-SRVR : STATUS AB00DD Latency=(08:31:19.651) latency=1 error=132
(08:31:21) MLAT-SRVR : STATUS 401DC6 Latency=(08:31:20.931) latency=0 error=113
(08:31:22) MLAT-SRVR : STATUS AB00DD Latency=(08:31:20.251) latency=2 error=126
(08:31:23) COMMON : LOCK: Blocked=0.00876 FEEDOUT(8) -> FEEDOUT
(08:31:23) COMMON : LOCK: Blocked=0.00892 FEEDOUT(8) -> FEEDOUT
(08:31:23) COMMON : LOCK: Blocked=0.00902 FEEDOUT(8) -> FEEDOUT
pi@ognpaw:~ $ netcat localhost 50002
@@@ procServ server started at: Sat Apr 13 11:17:09 2019
@@@ Child "./PilotAware-OGN.exe" started at: Sat Apr 13 11:17:09 2019
(PARSE-FAIL)HTTP_Server.Exec() ... Client from 10.10.10.8:48590
(PARSE-FAIL)HTTP_Server.Exec() ... Request for /
(08:32:27) TRX-RF : BCN-TX icao=FD4054 acft=1f lat=52.32267 lon=-0.70617 alt=92
PAWRT,40626E,TIMEOUT
(08:32:28) MLAT-SRVR : STATUS 400796 Latency=(08:32:26.522) latency=1 error=35
(08:32:29) MLAT-SRVR : STATUS 400796 Latency=(08:32:26.770) latency=2 error=117
(08:32:29) MLAT-SRVR : STATUS 400796 Latency=(08:32:27.490) latency=2 error=86
(08:32:29) MLAT-SRVR : STATUS 400CEE Latency=(08:32:26.876) latency=2 error=106
(08:32:29) MLAT-SRVR : STATUS 401DC6 Latency=(08:32:26.330) latency=3 error=241
(08:32:29) MLAT-SRVR : STATUS 400CEE Latency=(08:32:27.428) latency=2 error=111
(08:32:29) MLAT-SRVR : STATUS 400796 Time Reverse (Abort Update) 08:32:27 to 08:32:26
(08:32:30) INTF-OGN : APRS_SERVER: (recv) # aprsc 2.1.4-g408ed49 27 May 2019 08:32:30 GMT GLIDERN3 85.188.1.173:14580
(08:32:30) MLAT-SRVR : STATUS 400796 Latency=(08:32:27.829) latency=2 error=108
(08:32:30) MLAT-SRVR : STATUS 400CEE Latency=(08:32:30.402) latency=0 error=131
(PARSE-FAIL)HTTP_Server.Exec() ... Client from 10.10.10.8:48594
(08:32:32) MLAT-SRVR : STATUS 400CEE Latency=(08:32:31.639) latency=0 error=95
(08:32:32) COMMON : LOCK: Blocked=0.00928 FEEDOUT(23) -> FEEDOUT
(08:32:32) COMMON : LOCK: Blocked=0.00939 FEEDOUT(24) -> FEEDOUT
(08:32:32) COMMON : LOCK: Blocked=0.01185 FEEDOUT(27) -> FEEDOUT
(08:32:32) COMMON : LOCK: Blocked=0.00688 FEEDOUT(28) -> FEEDOUT
(08:32:32) COMMON : LOCK: Blocked=0.00716 FEEDOUT(28) -> FEEDOUT
(08:32:32) COMMON : LOCK: Blocked=0.00724 FEEDOUT(28) -> FEEDOUT
(08:32:32) COMMON : LOCK: Blocked=0.00729 FEEDOUT(28) -> FEEDOUT
(PARSE-FAIL)HTTP_Server.Exec() ... Request for /
(08:32:32) MLAT-SRVR : STATUS 400796 Latency=(08:32:30.950) latency=1 error=68
(08:32:33) MLAT-SRVR : STATUS 401DC6 Latency=(08:32:30.551) latency=2 error=217
pi@ognpaw:~ $ ps -auxwww | grep PilotAware-OGN
root 789 1.1 8.3 1016376 79052 pts/3 Ssl+ May26 13:10 ./PilotAware-OGN.exe
pi@ognpaw:~ $ sudo strace -p 789
Process 789 attached
futex(0x765174c8, FUTEX_WAIT, 800, NULL
pi@ognpaw:~ $ ps -T -p 789
PID SPID TTY TIME CMD
789 789 pts/3 00:00:00 PilotAware-OGN.
789 794 pts/3 00:00:09 PA_httpd
789 800 pts/3 00:00:03 OGN_recv
789 802 pts/3 00:00:36 OGN_send
789 803 pts/3 00:04:25 PA_RxTxRadio
789 804 pts/3 00:00:00 PA_TxSBS1
789 805 pts/3 00:00:23 PA_ParseSBS1
789 806 pts/3 00:00:00 aprs_local
789 807 pts/3 00:01:09 PA_SysMonitor
789 11651 pts/3 00:00:01 PA_TxSBS1
789 11667 pts/3 00:00:01 PA_TxSBS1
789 11679 pts/3 00:00:01 PA_TxSBS1
789 11721 pts/3 00:00:01 PA_TxSBS1
789 11736 pts/3 00:00:01 PA_TxSBS1
789 11753 pts/3 00:00:01 PA_TxSBS1
789 11759 pts/3 00:00:01 PA_TxSBS1
[~100 ocourances of PA_TxSBS1]
pi@ognpaw:~ $ sudo strace -p 794
Process 794 attached
nanosleep({0, 313648546}, 0x76d13da4) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [SEGV], 8) = 0
rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], 0}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [SEGV], NULL, 8) = 0
nanosleep({1, 0}, 0x76d13da4) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [SEGV], 8) = 0
rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], 0}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [SEGV], NULL, 8) = 0
pi@ognpaw:~ $ sudo strace -p 794
Process 794 attached
nanosleep({0, 313648546}, 0x76d13da4) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [SEGV], 8) = 0
rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], 0}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [SEGV], NULL, 8) = 0
nanosleep({1, 0}, 0x76d13da4) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [SEGV], 8) = 0
rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], 0}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [SEGV], NULL, 8) = 0
pi@ognpaw:~ $ sudo strace -p 794
Process 794 attached
nanosleep({0, 313648546}, 0x76d13da4) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [SEGV], 8) = 0
rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], 0}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [SEGV], NULL, 8) = 0
nanosleep({1, 0}, 0x76d13da4) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [SEGV], 8) = 0
rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], 0}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [SEGV], NULL, 8) = 0
pi@ognpaw:~ $ sudo strace -p 800
Process 800 attached
read(7, "HTTP_Server.Exec() ... Client fr"..., 1023) = 53
write(1, "(PARSE-FAIL)HTTP_Server.Exec() ."..., 64) = 64
nanosleep({0, 100000000}, NULL) = 0
read(7, "HTTP_Server.Exec() ... Request f"..., 1023) = 38
write(1, "(PARSE-FAIL)HTTP_Server.Exec() ."..., 49) = 49
nanosleep({0, 100000000}, NULL) = 0
pi@ognpaw:~ $ sudo strace -p 802
Process 802 attached
select(26, [25], [], NULL, {0, 5565}) = 0 (Timeout)
gettimeofday({1558945560, 952377}, NULL) = 0
clock_gettime(CLOCK_MONOTONIC, {68343, 542101910}) = 0
clock_gettime(CLOCK_MONOTONIC, {68343, 542165816}) = 0
select(26, [25], [], NULL, {0, 100000}) = 0 (Timeout)
gettimeofday({1558945561, 53272}, NULL) = 0
clock_gettime(CLOCK_MONOTONIC, {68343, 643005896}) = 0
clock_gettime(CLOCK_MONOTONIC, {68343, 643069385}) = 0
pi@ognpaw:~ $ sudo strace -p 803
Process 803 attached
nanosleep({0, 10000000}, NULL) = 0
read(12, 0x753fea18, 1024) = -1 EAGAIN (Resource temporarily unavailable)
gettimeofday({1558945602, 115036}, {0, 0}) = 0
nanosleep({0, 10000000}, NULL) = 0
read(12, 0x753fea18, 1024) = -1 EAGAIN (Resource temporarily unavailable)
gettimeofday({1558945602, 125400}, {0, 0}) = 0
pi@ognpaw:~ $ sudo strace -p 804
Process 804 attached
accept(9,
pi@ognpaw:~ $ sudo strace -p 805
Process 805 attached
select(25, [24], NULL, NULL, {9, 769852}) = 1 (in [24], left {9, 560389})
gettimeofday({1558945658, 434729}, NULL) = 0
read(24, "MSG,3,1,1,40650B,1,2019/05/27,08"..., 1024) = 123
gettimeofday({1558945658, 435286}, NULL) = 0
clock_gettime(CLOCK_MONOTONIC, {68441, 25215299}) = 0
clock_gettime(CLOCK_MONOTONIC, {68441, 25293216}) = 0
gettimeofday({1558945658, 435918}, NULL) = 0
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=118, ...}) = 0
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=118, ...}) = 0
gettimeofday({1558945658, 436749}, NULL) = 0
gettimeofday({1558945658, 436940}, NULL) = 0
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=118, ...}) = 0
write(2, "(08:27:38) MLAT-SRVR : ", 23) = 23
write(2, "STATUS 40650B Latency=(08:27:35."..., 56) = 56
gettimeofday({1558945658, 438028}, NULL) = 0
gettimeofday({1558945658, 438255}, NULL) = 0
gettimeofday({1558945658, 438486}, NULL) = 0
gettimeofday({1558945658, 438656}, NULL) = 0
pi@ognpaw:~ $ sudo strace -p 806
Process 806 attached
accept(8,
pi@ognpaw:~ $ sudo strace -p 807
Process 807 attached
nanosleep({0, 294656457}, 0x733fe79c) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [SEGV], 8) = 0
rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], 0}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [SEGV], NULL, 8) = 0
nanosleep({1, 0}, 0x733fe79c) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [SEGV], 8) = 0
rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], 0}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [SEGV], NULL, 8) = 0
pi@ognpaw:~ $ sudo strace -p 11651
Process 11651 attached
nanosleep({1, 0}, NULL) = 0
gettimeofday({1558945739, 270574}, NULL) = 0
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=118, ...}) = 0
clock_gettime(CLOCK_MONOTONIC, {68521, 860491088}) = 0
clock_gettime(CLOCK_MONOTONIC, {68521, 860559838}) = 0
gettimeofday({1558945739, 270996}, NULL) = 0
nanosleep({1, 0}, NULL) = 0
gettimeofday({1558945740, 271381}, NULL) = 0
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=118, ...}) = 0
clock_gettime(CLOCK_MONOTONIC, {68522, 861522577}) = 0
clock_gettime(CLOCK_MONOTONIC, {68522, 861652576}) = 0
gettimeofday({1558945740, 272181}, NULL) = 0
nanosleep({1, 0}, ^CProcess 11651 detached
Restarting the service with ^X it is fine again:
i@ognpaw:~ $ telnet localhost 80
Trying 127.0.0.1...
Connected to localhost.
Escape character is '^]'.
GET / HTTP/1.1
Host: ognpaw.unseen.org
HTTP/1.1 200 OK
Connection: close
Server: PilotAwarehttpd/0.1.0
Content-Length: 4833
Content-Type: text/html
<html><title><Status>[etc]
pi@ognpaw:~ $ netcat localhost 50002
@@@ procServ server started at: Sat Apr 13 11:17:09 2019
@@@ Child "./PilotAware-OGN.exe" started at: Mon May 27 08:34:24 2019
(PARSE-FAIL)HTTP_Server.Exec() ... Client from 10.10.10.8:49290
(PARSE-FAIL)HTTP_Server.Exec() ... Request for /
(08:38:34) MLAT-SRVR : STATUS 400F6F Latency=(08:38:33.115) latency=1 error=104
(08:38:34) TRX-RF : BCN-TX icao=FD4054 acft=1f lat=52.32267 lon=-0.70617 alt=92
(08:38:34) MLAT-SRVR : STATUS 401906 Latency=(08:38:32.819) latency=1 error=123
(08:38:34) MLAT-SRVR : STATUS 400CEE Latency=(08:38:32.442) latency=2 error=141
(08:38:35) MLAT-SRVR : STATUS 4035E1 Latency=(08:38:33.657) latency=1 error=181
(08:38:35) MLAT-SRVR : STATUS 40543F Latency=(08:38:34.490) latency=1 error=178
(08:38:35) MLAT-SRVR : STATUS 400CEE Latency=(08:38:34.363) latency=1 error=93
(08:38:36) INTF-OGN : APRS_SERVER: (recv) # aprsc 2.1.4-g408ed49 27 May 2019 08:38:36 GMT GLIDERN5 88.99.111.134:14580
(08:38:36) MLAT-SRVR : STATUS 401906 Latency=(08:38:35.555) latency=0 error=119
(08:38:37) MLAT-SRVR : STATUS 406FA5 Latency=(08:38:34.825) latency=2 error=410
(08:38:37) MLAT-SRVR : STATUS 40543F Latency=(08:38:36.578) latency=0 error=128
(08:38:38) MLAT-SRVR : STATUS 4076BF Latency=(08:38:35.102) latency=3 error=161
(08:38:38) MLAT-SRVR : STATUS 400CEE Latency=(08:38:37.413) latency=1 error=166
(08:38:38) MLAT-SRVR : STATUS 400CEE Latency=(08:38:38.103) latency=0 error=146
(PARSE-FAIL)HTTP_Server.Exec() ... Client from 10.10.10.8:49302
(PARSE-FAIL)HTTP_Server.Exec() ... Request for /
pi@ognpaw:~ $ ps -T -p 21293
PID SPID TTY TIME CMD
21293 21293 pts/3 00:00:00 PilotAware-OGN.
21293 21298 pts/3 00:00:00 PA_httpd
21293 21299 pts/3 00:00:00 OGN_recv
21293 21300 pts/3 00:00:00 OGN_send
21293 21301 pts/3 00:00:01 PA_RxTxRadio
21293 21303 pts/3 00:00:00 PA_TxSBS1
21293 21304 pts/3 00:00:03 PA_ParseSBS1
21293 21305 pts/3 00:00:00 aprs_local
21293 21306 pts/3 00:00:00 PA_SysMonitor
21293 21639 pts/3 00:00:00 PA_TxSBS1
Cheers
Kev