[nos-bbs] jnos quits after receiving proposal

[Michael Fox - N6MEF]

N6MEF is running JNOS 2.0j.7v with "bleeding" updates
N6RME is running FBB v7.05f

I've only seen this once since installing the "bleeding edge" updates.  
I'm reporting it for completeness.

Summary:  JNOS receives a proposal and quits right away.  Nos.log doesn't
say what happened.  Later, JNOS accepts the same proposal and it is
successfully forwarded.

Suggestion:  It would be nice if JNOS logged why it quit.

Details:

N6MEF nos.log:

At 22:08, we see an incoming proposal followed by an exit.  No explanation
of what happened.
At 22:15, we see the same proposal accepted and forwarded.

Sat Apr 16 22:08:10 2016  - AT command: mbox kick N6rme+|325+
Sat Apr 16 22:08:11 2016  67.174.37.45:6301 - MBOX (n6rme) connected
Sat Apr 16 22:08:16 2016  67.174.37.45:6301 - MBOX (n6rme) forwarding
Sat Apr 16 22:08:16 2016  67.174.37.45:6301 - MBOX (n6rme) incoming proposal
FA B CX2SA AMSAT SAT ANS-108.01 25136
Sat Apr 16 22:08:16 2016  67.174.37.45:6301 - MBOX (n6rme) fwd exit

Sat Apr 16 22:15:14 2016  67.174.37.45:54360 - MBOX (n6rme) login
Sat Apr 16 22:15:14 2016  67.174.37.45:54360 - MBOX (n6rme) open
Sat Apr 16 22:15:14 2016  67.174.37.45:54360 - MBOX (n6rme) forwarding
Sat Apr 16 22:15:14 2016  67.174.37.45:54360 - MBOX (n6rme) incoming
proposal FA B CX2SA AMSAT SAT ANS-108.01 25136
Sat Apr 16 22:15:14 2016  67.174.37.45:54360 - MBOX (n6rme) our response FS
+
Sat Apr 16 22:15:15 2016  67.174.37.45:54360 - MBOX (n6rme) lzhuf uncompress
12208/25210 = 51 percent
Sat Apr 16 22:15:15 2016  67.174.37.45:54360 - MBOX (n6rme) ANS-108.01
received
Sat Apr 16 22:15:15 2016  67.174.37.45:54360 - MBOX (n6rme) exit


Telnet trace:

At 22:08, JNOS connects to FBB.  FBB made a proposal and JNOS quits right
away.  Weird.
At 22:15, FBB connects to JNOS.  FBB makes the same proposal and JNOS
accepts it.  Forwarding occurs.

Date/Time					Src	Dst	Telnet Data
Field

Apr 16, 2016 22:08:12.063014000	n6rme	N6MEF	\x0d\x0a,N6RME BBS. TELNET
Access\x0d\x0a,\x0d\x0a,Callsign : 
Apr 16, 2016 22:08:14.100608000	N6MEF	n6rme	n6mef\x0d
Apr 16, 2016 22:08:14.187382000	n6rme	N6MEF	Password : 
Apr 16, 2016 22:08:16.114998000	N6MEF	n6rme	********\x0d
Apr 16, 2016 22:08:16.232203000	n6rme	N6MEF	\x0d\x0a,Logon Ok. Type NP
to change password.\x0d\x0a,\x0d\x0a
Apr 16, 2016 22:08:16.257993000	n6rme	N6MEF
[FBB-7.05f-AB1FHMR$]\x0d\x0a,N6RME Mailbox, QTH Placerville.\x0d\x0a,(1)
N6RME B
Apr 16, 2016 22:08:16.280541000	n6rme	N6MEF	BS>\x0d\x0a
Apr 16, 2016 22:08:16.288993000	N6MEF	n6rme
[JNOS-2.0j.7v.XSC32.3-B1FHIM$]\x0dFF\x0d
Apr 16, 2016 22:08:16.464636000	n6rme	N6MEF	FA B CX2SA AMSAT SAT
ANS-108.01 25136\x0d\x0a,F> 73\x0d\x0a
Apr 16, 2016 22:08:16.465093000	N6MEF	n6rme	FQ\x0d
Apr 16, 2016 22:08:16.621132000	n6rme	N6MEF	*** Protocol error: Answer
to proposals must be either \"FF\" not 
Apr 16, 2016 22:08:16.621168000	n6rme	N6MEF	\"FS\".\x0d\x0a

Apr 16, 2016 22:15:14.468616000	N6MEF	n6rme	\x0d\x0a,JNOS
(n6mef.ampr.org)\x0d\x0a,\x0d\x0a,login: 
Apr 16, 2016 22:15:14.551428000	n6rme	N6MEF
N6RME\x0d\x0a,bD9fZb91{4\x0d\x0a
Apr 16, 2016 22:15:14.551899000	N6MEF	n6rme	Password: 
Apr 16, 2016 22:15:14.574053000	N6MEF	n6rme
\x0d\x0a,[JNOS-2.0j.7v.XSC32.3-BFHIM$]\x0d\x0a,>\x0d\x0a
Apr 16, 2016 22:15:14.655179000	n6rme	N6MEF
[FBB-7.05f-ABFHM$]\x0d\x0a,FA B CX2SA AMSAT SAT ANS-108.01 25136\x0d\x0a,F>
73\x0d\x0a
Apr 16, 2016 22:15:14.656592000	N6MEF	n6rme	FS +\x0d\x0a
Apr 16, 2016 22:15:14.810606000	n6rme	N6MEF	\x013ANS-108 AMSAT News
Service Weekly Bulletins
Apr 16, 2016 22:15:14.832226000	n6rme	N6MEF	[long binary data not shown
here - let me know if you need to see it]
Apr 16, 2016 22:15:15.456376000	N6MEF	n6rme	FF\x0d\x0a
Apr 16, 2016 22:15:15.630907000	n6rme	N6MEF	FQ\x0d


I suppose it's possible that some other telnet error occurred, causing JNOS
to quit.  But from an FBB protocol standpoint, I don't see why it quit the
first session.

Again, it has only happened once in the last 2 days.  So unless it's
something obvious, or it starts to occur more often, perhaps we just ignore
it.

Michael
N6MEF