Bug #305

tcpgate unittest error 13

Added by Madars Vitolins 3 months ago. Updated 3 months ago.

Status:ClosedStart date:04/13/2018
Priority:NormalDue date:
Assignee:-% Done:

100%

Category:-
Target version:-

Description

Sleep 90 - let async calls to complete...
>>> Run offset tests, len not included
>>> Run offset tests, swap bytes, len included
>>> Run async calls, sync invocation
>>> Run async calls
>>> No connection
Server executable = tcpgatesv    Id = 210 :    Shutdown succeeded.
Shutdown finished. 1 processes stopped.
Server executable = tcpgatesv    Id = 230 :    Shutdown succeeded.
Shutdown finished. 1 processes stopped.
ndrxd PID (from PID file): 28124
exec tcpgatesv -k 0myWI5nu -i 210 -e /home/user1/modules/endurox-connect/tests/02_tcpgatesv/runtime/log/tcpgatesv-async-passive.log -r --  :
    process id=30429 ... Started.
Startup finished. 1 processes started.
ndrxd PID (from PID file): 28124
exec tcpgatesv -k 0myWI5nu -i 230 -e /home/user1/modules/endurox-connect/tests/02_tcpgatesv/runtime/log/tcpgatesv-pers-sync-passive.log -r --  :
    process id=30434 ... Started.
Startup finished. 1 processes started.
 >>> Run Correlation...
>>>Run Correlation, timeout
>>> Persistent, Sync connection, call
>>> Persistent, Sync connection, call, timeout
>>> Persistent, Sync connection, call, no-connection, try from Passive end.
>>> Nonpersistent, normal call
>>> Nonpersistent, timeout
>>> Nonpersistent, cannot connect
>>> Have some test where we overload the channel - i.e.
testcl corrsim 40 TCP_P_ASYNC_P failed
Test exiting with: 13
ndrxd PID (from PID file): 28124
Server executable = cpmsrv    Id = 9999 :    Shutdown succeeded.
Server executable = tcpgatesv    Id = 350 :    Shutdown succeeded.
Server executable = tcpgatesv    Id = 340 :    Shutdown succeed

u.gz (6.16 MB) Madars Vitolins, 04/13/2018 11:31 PM

History

#1 Updated by Madars Vitolins 3 months ago

attached uvlog

#2 Updated by Madars Vitolins 3 months ago

Seems at this step:

000.000|c-active.0.log|T:TCPG:4:linux   :28224:7f208701b700:014:20180413:172419784:tions.go:0479:Conn: 7115697180131721218 polling...
000.000|c-active.0.log| :NDRX:5:linux   :28224:7f208bdb18c0:000:20180413:172419784:spatch.c:1141:Poll says: 1
000.000|c-active.0.log| :NDRX:5:linux   :28224:7f208bdb18c0:000:20180413:172419784:spatch.c:1195:Receiving 0, user data: 34, fd: 34, evmqd: 34, is_mq_only: -1, G_pollext=(nil)
000.000|c-active.0.log| :NDRX:5:linux   :28224:7f208bdb18c0:000:20180413:172419784:spatch.c:1263:Got request on logical channel 2, fd: 34
000.000|c-active.0.log| :NDRX:5:linux   :28224:7f208bdb18c0:000:20180413:172419784:spatch.c:0740:Got command: 1
000.000|c-active.0.log| :NDRX:5:linux   :28224:7f208bdb18c0:000:20180413:172419784:spatch.c:0240:got call, cd: 0 timestamp: 1523640259 (id: 01523640259) callseq: 0, svc: TCP_P_ASYNC_A, flags: 4, call age: 0, data_len: 2196, caller: srv,te
stsv,500,28220,0,1  reply_to: /test1,srv,reply,testsv,500,28220, clttout: 90
000.000|c-active.0.log| :NDRX:5:linux   :28224:7f208bdb18c0:000:20180413:172419784:ed_ubf.c:0116:Entering UBF_prepare_incoming
000.000|c-active.0.log| :NDRX:5:linux   :28224:7f208bdb18c0:000:20180413:172419784:ed_ubf.c:0202:UBF_prepare_incoming: Incoming buffer where missing - allocating new (size: 2196)!
000.000|c-active.0.log| :NDRX:5:linux   :28224:7f208bdb18c0:000:20180413:172419784:ed_buf.c:0199:ndrx_tpalloc: type=NULL, subtype=NULL len=2196
000.000|c-active.0.log| :NDRX:5:linux   :28224:7f208bdb18c0:000:20180413:172419784:ed_buf.c:0241:ndrx_tpalloc: type=NULL subtype=NULL len=2196 allocated=0x25eb7c0
000.000|c-active.0.log| :NDRX:5:linux   :28224:7f208bdb18c0:000:20180413:172419784:spatch.c:0292:Buffer=0x25eb7c0 autoalloc=1
000.000|c-active.0.log| :NDRX:5:linux   :28224:7f208bdb18c0:000:20180413:172419784:misrv.go:0105:_GO_SVC_ENTRY entry- getting context, current ATMI context: 0x7f208bc8e010
000.000|c-active.0.log|T:TCPG:5:linux   :28224:7f208bdb18c0:000:20180413:172419784:_tplog.c:0099:Incoming request:
000.000|c-active.0.log|EX_NETCONNID     7115697180131721217
000.000|c-active.0.log|((BFLDID32)33555089)     37702
000.000|c-active.0.log|((BFLDID32)33555091)     9999
000.000|c-active.0.log|((BFLDID32)67109524)     A
000.000|c-active.0.log|EX_NETGATEWAY    TCP_P_ASYNC_A
000.000|c-active.0.log|((BFLDID32)167772816)    127.0.0.1
000.000|c-active.0.log|((BFLDID32)167772818)    127.0.0.1
000.000|c-active.0.log|EX_NETDATA       Aghi\05\06\07\08\09\0a\0b\0c\0d\0e\0f\10\11\12\13\14\15\16\17\18\19\1a\1b\1c\1d\1e\1f !"#$%&'()*+,-./0123456789:;<=>?@ABCDEFGHIJKLMNOPQRSTUVWXYZ[\\]^_`abcdefghijklmnopqrstuvwxyz{|}~\7f\80\81\82\83\8
4\85\86\87\88\89\8a\8b\8c\8d\8e\8f\90\91\92\93\94\95\96\97\98\99\9a\9b\9c\9d\9e\9f\a0\a1\a2\a3\a4\a5\a6\a7\a8\a9\aa\ab\ac\ad\ae\af\b0\b1\b2\b3\b4\b5\b6\b7\b8\b9\ba\bb\bc\bd\be\bf\c0\c1\c2\c3\c4\c5\c6\c7\c8\c9\ca\cb\cc\cd\ce\cf\d0\d1\d2\d3
\d4\d5\d6\d7\d8\d9\da\db\dc\dd\de\df\e0\e1\e2\e3\e4\e5\e6\e7\e8\e9\ea\eb\ec\ed\ee\ef\f0\f1\f2\f3\f4\f5\f6\f7\f8\f9\fa\fb\fc\fd\fe\ff\00\01\05\06\07\05\06\07\08\09\0a\0b\0c\0d\0e\0f\10\11\12\13\14\15\16\17\18\19\1a\1b\1c\1d\1e\1f !"#$%&'()
*+,-./0123456789:;<=>?@ABCDEFGHIJKLMNOPQRSTUVWXYZ[\\]^_`abcdefghijklmnopqrstuvwxyz{|}~\7f\80\81\82\83\84\85\86\87\88\89\8a\8b\8c\8d\8e\8f\90\91\92\93\94\95\96\97\98\99\9a\9b\9c\9d\9e\9f\a0\a1\a2\a3\a4\a5\a6\a7\a8\a9\aa\ab\ac\ad\ae\af\b0\b
1\b2\b3\b4\b5\b6\b7\b8\b9\ba\bb\bc\bd\be\bf\c0\c1\c2\c3\c4\c5\c6\c7\c8\c9\ca\cb\cc\cd\ce\cf\d0\d1\d2\d3\d4\d5\d6\d7\d8\d9\da\db\dc\dd\de\df\e0\e1\e2\e3\e4\e5\e6\e7\e8\e9\ea\eb\ec\ed\ee\ef\f0\f1\f2\f3\f4\f5\f6\f7\f8\f9\fa\fb\fc\fd\fe\ff\00
\01\05\06\07\05\06\07\08\09\0a\0b\0c\0d\0e\0f\10\11\12\13\14\15\16\17\18\19\1a\1b\1c\1d\1e\1f !"#$%&'()*+,-./0123456789:;<=>?@ABCDEFGHIJKLMNOPQRSTUVWXYZ[\\]^_`abcdefghijklmnopqrstuvwxyz{|}~\7f\80\81\82\83\84\85\86\87\88\89\8a\8b\8c\8d\8e\
8f\90\91\92\93\94\95\96\97\98\99\9a\9b\9c\9d\9e\9f\a0\a1\a2\a3\a4\a5\a6\a7\a8\a9\aa\ab\ac\ad\ae\af\b0\b1\b2\b3\b4\b5\b6\b7\b8\b9\ba\bb\bc\bd\be\bf\c0\c1\c2\c3\c4\c5\c6\c7\c8\c9\ca\cb\cc\cd\ce\cf\d0\d1\d2\d3\d4\d5\d6\d7\d8\d9\da\db\dc\dd\d
e\df\e0\e1\e2\e3\e4\e5\e6\e7\e8\e9\ea\eb\ec\ed\ee\ef\f0\f1\f2\f3\f4\f5\f6\f7\f8\f9\fa\fb\fc\fd\fe\ff\00\01\05\06\07\05\06\07\08\09\0a\0b\0c\0d\0e\0f\10\11\12\13\14\15\16\17\18\19\1a\1b\1c\1d\1e\1f !"#$%&'()*+,-./0123456789:;<=>?@ABCDEFGHI
JKLMNOPQRSTUVWXYZ[\\]^_`abcdefghijklmnopqrstuvwxyz{|}~\7f\80\81\82\83\84\85\86\87\88\89\8a\8b\8c\8d\8e\8f\90\91\92\93\94\95\96\97\98\99\9a\9b\9c\9d\9e\9f\a0\a1\a2\a3\a4\a5\a6\a7\a8\a9\aa\ab\ac\ad\ae\af\b0\b1\b2\b3\b4\b5\b6\b7\b8\b9\ba\bb\
bc\bd\be\bf\c0\c1\c2\c3\c4\c5\c6\c7\c8\c9\ca\cb\cc\cd\ce\cf\d0\d1\d2\d3\d4\d5\d6\d7\d8\d9\da\db\dc\dd\de\df\e0\e1\e2\e3\e4\e5\e6\e7\e8\e9\ea\eb\ec\ed\ee\ef\f0\f1\f2\f3\f4\f5\f6\f7\f8\f9\fa\fb\fc\fd\fe\ff\00\01\05\06\07\05\06\07\08\09\0a\0
b\0c\0d\0e\0f\10\11\12\13\14\15\16\17\18\19\1a\1b\1c\1d\1e\1f !"#$%&'()*+,-./0123456789:;<=>?@ABCDEFGHIJKLMNOPQRSTUVWXYZ[\\]^_`abcdefghijklmnopqrstuvwxyz{|}~\7f\80\81\82\83\84\85\86\87\88\89\8a\8b\8c\8d\8e\8f\90\91\92\93\94\95\96\97\98\99
\9a\9b\9c\9d\9e\9f\a0\a1\a2\a3\a4\a5\a6\a7\a8\a9\aa\ab\ac\ad\ae\af\b0\b1\b2\b3\b4\b5\b6\b7\b8\b9\ba\bb\bc\bd\be\bf\c0\c1\c2\c3\c4\c5\c6\c7\c8\c9\ca\cb\cc\cd\ce\cf\d0\d1\d2\d3\d4\d5\d6\d7\d8\d9\da\db\dc\dd\de\df\e0\e1\e2\e3\e4\e5\e6\e7\e8\
e9\ea\eb\ec\ed\ee\ef\f0\f1\f2\f3\f4\f5\f6\f7\f8\f9\fa\fb\fc\fd\fe\ff\00\01\05\06\07\05\06\07\08\09\0a\0b\0c\0d\0e\0f\10\11\12\13\14\15\16\17\18\19\1a\1b\1c\1d\1e\1f !"#$%&'()*+,-./0123456789:;<=>?@ABCDEFGHIJKLMNOPQRSTUVWXYZ[\\]^_`abcdefgh
ijklmnopqrstuvwxyz{|}~\7f\80\81\82\83\84\85\86\87\88\89\8a\8b\8c\8d\8e\8f\90\91\92\93\94\95\96\97\98\99\9a\9b\9c\9d\9e\9f\a0\a1\a2\a3\a4\a5\a6\a7\a8\a9\aa\ab\ac\ad\ae\af\b0\b1\b2\b3\b4\b5\b6\b7\b8\b9\ba\bb\bc\bd\be\bf\c0\c1\c2\c3\c4\c5\c6
\c7\c8\c9\ca\cb\cc\cd\ce\cf\d0\d1\d2\d3\d4\d5\d6\d7\d8\d9\da\db\dc\dd\de\df\e0\e1\e2\e3\e4\e5\e6\e7\e8\e9\ea\eb\ec\ed\ee\ef\f0\f1\f2\f3\f4\f5\f6\f7\f8\f9\fa\fb\fc\fd\fe\ff\00\01\05\06\07\05\06\07\08\09\0a\0b\0c\0d\0e\0f\10\11\12\13\14\15\
16\17\18\19\1a\1b\1c\1d\1e\1f !"#$%&'()*+,-./0123456789:;<=>?@ABCDEFGHIJKLMNOPQRSTUVWXYZ[\\]^_`abcdefghijklmnopqrstuvwxyz{|}~\7f\80\81\82\83\84\85\86\87\88\89\8a\8b\8c\8d\8e\8f\90\91\92\93\94\95\96\97\98\99\9a\9b\9c\9d\9e\9f\a0\a1\a2\a3\a
4\a5\a6\a7\a8\a9\aa\ab\ac\ad\ae\af\b0\b1\b2\b3\b4\b5\b6\b7\b8\b9\ba\bb\bc\bd\be\bf\c0\c1\c2\c3\c4\c5\c6\c7\c8\c9\ca\cb\cc\cd\ce\cf\d0\d1\d2\d3\d4\d5\d6\d7\d8\d9\da\db\dc\dd\de\df\e0\e1\e2\e3\e4\e5\e6\e7\e8\e9\ea\eb\ec\ed\ee\ef\f0\f1\f2\f3
\f4\f5\f6\f7\f8\f9\fa\fb\fc\fd\fe\ff\00\01\05\06\07\05\06\07\08\09\0a\0b\0c\0d\0e\0f\10\11\12\13\14\15\16\17\18\19\1a\1b\1c\1d\1e\1f !"#$%&'()*+,-./0123456789:;<=>?@ABCDEFGHIJKLMNOPQRSTUVWXYZ[\\]^_`abcdefghijklmnopqrstuvwxyz{|}~\7f\80\81\
82\83\84\85\86\87\88\89\8a\8b\8c\8d\8e\8f\90\91\92\93\94\95\96\97\98\99\9a\9b\9c\9d\9e\9f\a0\a1\a2\a3\a4\a5\a6\a7\a8\a9\aa\ab\ac\ad\ae\af\b0\b1\b2\b3\b4\b5\b6\b7\b8\b9\ba\bb\bc\bd\be\bf\c0\c1\c2\c3\c4\c5\c6\c7\c8\c9\ca\cb\cc\cd\ce\cf\d0\d
1\d2\d3\d4\d5\d6\d7\d8\d9\da\db\dc\dd\de\df\e0\e1\e2\e3\e4\e5\e6\e7\e8\e9\ea\eb\ec\ed\ee\ef\f0\f1\f2\f3\f4\f5\f6\f7\f8\f9\fa\fb\fc\fd\fe\ff\00
000.000|ync-active.log|N:NDRX:5:linux   :28224:7f208bdb18c0:000:20180413:172419784:misrv.go:0111:_GO_SVC_ENTRY got context 0x7f208bc8e010, dispatching call to GO space name: [TCP_P_ASYNC_A] fname: [TCP_P_ASYNC_A]
000.001|c-active.0.log| :NDRX:5:linux   :28224:7f208bdb18c0:000:20180413:172419785:ed_buf.c:0279:ndrx_tprealloc buf=0x25eb7c0, len=3220
000.000|c-active.0.log| :NDRX:5:linux   :28224:7f208bdb18c0:000:20180413:172419785:ed_buf.c:0289:ndrx_tprealloc buf=0x25eb7c0 autoalloc=1
000.000|c-active.0.log| :NDRX:5:linux   :28224:7f208bdb18c0:000:20180413:172419785:verapi.c:0337:tpsrvgetctxdata2: returning 0x25eb7c0 (last call cd: 0)
000.000|c-active.0.log|T:TCPG:4:linux   :28224:7f208bdb18c0:000:20180413:172419785:atesv.go:0189:Waiting for free XATMI out object
000.000|c-active.0.log|T:TCPG:4:linux   :28224:7f208bdb18c0:000:20180413:172419785:ipool.go:0108:Got free XATMI out object id=3 
000.000|c-active.0.log|T:TCPG:4:linux   :28224:7f208bdb18c0:000:20180413:172419785:atesv.go:0191:Got XATMI out object
000.000|c-active.0.log| :NDRX:5:linux   :28224:7f208bdb18c0:000:20180413:172419785:return.c:0599:Not jumping - as integra mode!
000.000|c-active.0.log| :NDRX:3:linux   :28224:7f208bdb18c0:000:20180413:172419785:spatch.c:0428:tpcontinue() issued from integra (no longjmp)!
000.000|c-active.0.log|  0000  41 63 64 65 04 05 06 07 08 09 0a 0b 0c 0d 0e 0f  Acde............
000.000|c-active.0.log|  0010  10 11 12 13 14 15 16 17 18 19 1a 1b 1c 1d 1e 1f  ................
000.000|c-active.0.log|  0020  20 21 22 23 24 25 26 27 28 29 2a 2b 2c 2d 2e 2f   !"#$%&'()*+,-./
000.000|c-active.0.log|  0030  30 31 32 33 34 35 36 37 38 39 3a 3b 3c 3d 3e 3f  0123456789:;<=>?

The track of Aghi is lost.

#3 Updated by Madars Vitolins 3 months ago

000.000|c-active.9.log|T:TCPG:4:linux   :28224:7f208701b700:009:20180413:172419785:miout.go:0118:About to restore context data in goroutine...
000.000|c-active.9.log|T:TCPG:4:linux   :28224:7f208701b700:009:20180413:172419785:miout.go:0151:Waiting for connection...
000.000|c-active.9.log|T:TCPG:4:linux   :28224:7f208701b700:009:20180413:172419785:tions.go:0266:Compiled id: 7115697180131721217, tstamp: 424128602751, simple id: 1
000.000|c-active.9.log|T:TCPG:4:linux   :28224:7f208701b700:009:20180413:172419785:tions.go:0269:Looks like compiled connection id - lookup by hash

probably it is thread #9 which for some reason did not get connection? - we need some logging here at point of restore needs some correlator in log for main routine...

#4 Updated by Madars Vitolins 3 months ago

mabe the channel was overfilled with free connections and it was unable to put conns back.

#5 Updated by Madars Vitolins 3 months ago

?????????????????????????????
000.000|c-active.0.log|T:TCPG:4:linux   :28224:7f208a073700:014:20180413:172419741:tions.go:0428:Putting connection 2/7115697180131721218 in RR list
000.000|c-active.0.log|T:TCPG:4:linux   :28224:7f208a073700:014:20180413:172419741:tions.go:0432:After putting 2/7115697180131721218 in RR list
000.000|c-active.0.log|T:TCPG:4:linux   :28224:7f208a073700:014:20180413:172419741:tions.go:0479:Conn: 7115697180131721218 polling...
000.000|c-active.0.log|T:TCPG:4:linux   :28224:7f208a073700:014:20180413:172419748:tions.go:0428:Putting connection 2/7115697180131721218 in RR list
000.000|c-active.0.log|T:TCPG:4:linux   :28224:7f208a073700:014:20180413:172419748:tions.go:0432:After putting 2/7115697180131721218 in RR list
?????????????????????????????

#7 Updated by Madars Vitolins 3 months ago

  • Status changed from New to Resolved
  • % Done changed from 0 to 100

#8 Updated by Madars Vitolins 3 months ago

  • Status changed from Resolved to Closed

Also available in: Atom PDF