Re: [Bug-apl] [bug-apl] SVN 346 APserver error on startup

[Juergen Sauermann]

Hi,

I added some printouts showing port numbers involved in the start-up of apl and APserver.
APnnn shall not be started manually.

I also did a bind() on the client TCP socket even though that should not make a difference (but who knows?).

To see these printouts start APserver with -v and apl with -l37 (= log startup messages).

On your boxed, please do the following:

1. Check IP address on lo:


address@hidden:~/apl/apl-1.3/src$ ifconfig lo
lo        Link encap:Local Loopback 
          inet addr:127.0.0.1  Mask:255.0.0.0
          inet6 addr: ::1/128 Scope:Host
          UP LOOPBACK RUNNING  MTU:65536  Metric:1
          RX packets:56460 errors:0 dropped:0 overruns:0 frame:0
          TX packets:56460 errors:0 dropped:0 overruns:0 carrier:0
          collisions:0 txqueuelen:0
          RX bytes:30060566 (30.0 MB)  TX bytes:30060566 (30.0 MB)


2. Check TCP connectivity (none of the apl/APnnn/APserver processes running)

address@hidden:~/apl/apl-1.3/src$ nc -l 127.0.0.1 16366  (in shell/window 1)
address@hidden:~/apl/apl-1.3/src$ nc 127.0.0.1 16366     (in shell/window 2)

Window 1:
Hello ←←←
World →→→

Window2:
Hello ←←←
World →→→


3. check iptables:

address@hidden:~/apl/apl-1.3/src$ sudo iptables -L
Chain INPUT (policy ACCEPT)
target     prot opt source               destination        

Chain FORWARD (policy ACCEPT)
target     prot opt source               destination        

Chain OUTPUT (policy ACCEPT)
target     prot opt source               destination    


4. tcpdump apl - APserver connections setup (start apl with no options):

address@hidden:~/apl/apl-1.3/src$ sudo tcpdump -i any -n port 16366
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on any, link-type LINUX_SLL (Linux cooked), capture size 65535 bytes
16:16:46.740744 IP 127.0.0.1.47228 > 127.0.0.1.16366: Flags [S], seq 2243567161, win 43690, options [mss 65495,sackOK,TS val 2777964 ecr 0,nop,wscale 7], length 0
16:16:46.740761 IP 127.0.0.1.16366 > 127.0.0.1.47228: Flags [R.], seq 0, ack 2243567162, win 0, length 0
16:16:46.761137 IP 127.0.0.1.48372 > 127.0.0.1.16366: Flags [S], seq 2243567164, win 43690, options [mss 65495,sackOK,TS val 2777969 ecr 0,nop,wscale 7], length 0
16:16:46.761156 IP 127.0.0.1.16366 > 127.0.0.1.48372: Flags [S.], seq 3037122167, ack 2243567165, win 43690, options [mss 65495,sackOK,TS val 2777969 ecr 2777969,nop,wscale 7], length 0
16:16:46.761173 IP 127.0.0.1.48372 > 127.0.0.1.16366: Flags [.], ack 1, win 342, options [nop,nop,TS val 2777969 ecr 2777969], length 0
16:16:46.783331 IP 127.0.0.1.48372 > 127.0.0.1.16366: Flags [P.], seq 1:2, ack 1, win 342, options [nop,nop,TS val 2777975 ecr 2777969], length 1
16:16:46.783371 IP 127.0.0.1.16366 > 127.0.0.1.48372: Flags [.], ack 2, win 342, options [nop,nop,TS val 2777975 ecr 2777975], length 0
16:16:46.783430 IP 127.0.0.1.16366 > 127.0.0.1.48372: Flags [P.], seq 1:20361, ack 2, win 342, options [nop,nop,TS val 2777975 ecr 2777975], length 20360
16:16:46.783506 IP 127.0.0.1.48372 > 127.0.0.1.16366: Flags [.], ack 20361, win 1024, options [nop,nop,TS val 2777975 ecr 2777975], length 0
16:16:46.787933 IP 127.0.0.1.41553 > 127.0.0.1.16366: Flags [S], seq 9629428, win 43690, options [mss 65495,sackOK,TS val 2777976 ecr 0,nop,wscale 7], length 0
16:16:46.787953 IP 127.0.0.1.16366 > 127.0.0.1.41553: Flags [S.], seq 1225625404, ack 9629429, win 43690, options [mss 65495,sackOK,TS val 2777976 ecr 2777976,nop,wscale 7], length 0
16:16:46.787970 IP 127.0.0.1.41553 > 127.0.0.1.16366: Flags [.], ack 1, win 342, options [nop,nop,TS val 2777976 ecr 2777976], length 0
16:16:46.808520 IP 127.0.0.1.41553 > 127.0.0.1.16366: Flags [P.], seq 1:2, ack 1, win 342, options [nop,nop,TS val 2777981 ecr 2777976], length 1
16:16:46.808564 IP 127.0.0.1.16366 > 127.0.0.1.41553: Flags [.], ack 2, win 342, options [nop,nop,TS val 2777981 ecr 2777981], length 0
16:16:46.808623 IP 127.0.0.1.16366 > 127.0.0.1.41553: Flags [P.], seq 1:20361, ack 2, win 342, options [nop,nop,TS val 2777981 ecr 2777981], length 20360
16:16:46.808732 IP 127.0.0.1.41553 > 127.0.0.1.16366: Flags [.], ack 20361, win 1024, options [nop,nop,TS val 2777981 ecr 2777981], length 0
16:16:46.808791 IP 127.0.0.1.41553 > 127.0.0.1.16366: Flags [P.], seq 2:20362, ack 20361, win 1024, options [nop,nop,TS val 2777981 ecr 2777981], length 20360
16:16:46.808837 IP 127.0.0.1.16366 > 127.0.0.1.41553: Flags [.], ack 20362, win 1024, options [nop,nop,TS val 2777981 ecr 2777981], length 0
16:16:46.809063 IP 127.0.0.1.48372 > 127.0.0.1.16366: Flags [P.], seq 2:3, ack 20361, win 1024, options [nop,nop,TS val 2777981 ecr 2777975], length 1
16:16:46.809149 IP 127.0.0.1.16366 > 127.0.0.1.48372: Flags [P.], seq 20361:40721, ack 3, win 342, options [nop,nop,TS val 2777981 ecr 2777981], length 20360
16:16:46.809282 IP 127.0.0.1.48372 > 127.0.0.1.16366: Flags [P.], seq 3:4, ack 40721, win 1024, options [nop,nop,TS val 2777981 ecr 2777981], length 1
16:16:46.845900 IP 127.0.0.1.16366 > 127.0.0.1.48372: Flags [.], ack 4, win 342, options [nop,nop,TS val 2777991 ecr 2777981], length 0
16:16:46.845953 IP 127.0.0.1.48372 > 127.0.0.1.16366: Flags [P.], seq 4:16, ack 40721, win 1024, options [nop,nop,TS val 2777991 ecr 2777991], length 12
16:16:46.846010 IP 127.0.0.1.16366 > 127.0.0.1.48372: Flags [.], ack 16, win 342, options [nop,nop,TS val 2777991 ecr 2777991], length 0

The above shows APserver on port 16366, a connection from apl (ephemeral port 47228) to APserver,
followed by a connection from APnnn (ephemereal ort 48372) to APserver.

/// Jürgen





On 06/29/2014 04:54 PM, apm wrote:

On 29/06/14 05:16 AM, Juergen Sauermann wrote:

Hi apm,

looks like APserver is not running.

Normally APserver is forked automatically by the apl interpreter,
but that can fail for numerous reasons. For the automatic
start of APserver it must be:

- executable, and
- located in the same directory as the apl interpreter.

You can also start APserver manually before the apl interpreter.

Other reasons can be security related, such as a firewall preventing
TCP connections from the apl interpreter to APserver on 127.0.0.1.

/// Jürgen

I checked the system monitor and in SVN 346 APnnn, APserver and apl all start, however, apl is unresponsive until I press ctrl-C which closes APnnn and APserver and results in the message on the apl console:

*** Failed to start APnnn: processor 1001 will not accept incoming shared variable offers. Expect surprises.

It appears in SVN 346 there is something freezing apl when APnnn, APserver and apl first start up together.

However, if I startup as follows:

$ APserver &
$ APnnn &
$ apl

apl starts up without error messages.

When I separately start up the three programs as above, after I quit apl (")off" in console), APserver and APnnn remain running. If I "killall APserver" I get a normal exit, but when I "killall APnnn" I get 16 sets of socket error messages like the following:

UdpSocket::sendto() failed: Invalid argument
socket was created at: ../Svar_DB_memory.cc:610
local address:  127.0.0.1:36419
remote address: 127.0.0.1:0

I tried the separate startup with SVN 344 and it behaves the same way. It seems some sort of timing issue was introduced in SVN 345 or SVN 346 whereby apl is querying something before it is ready giving rise to the startup message:

execve() failed
::connect() to existing APserver failed: Connection refused
*** using local Svar_DB cache