orignal
lEKI: 192.181.7.4 => [2357:190] [itag:1880421834]
orignal
hmm
orignal
one more SSU2 router through instroducer
zzz
over 40 connections with KyY2 since restart, but always very short, and no late acks. I don't think we're going to catch anything with this configuration
R4SAS
enable transit again?
R4SAS
238M of logs since yesterday
R4SAS
)))
orignal
who cares )
R4SAS
one thing I got when greping logs for Peer Test is that one:
R4SAS
SSU2: Unexpected PeerTest message SourceConnID=6562166969856000023 DestConnID=11884577103853551592
R4SAS
sometimes I got 68
R4SAS
ans 2 too
R4SAS
and*
orignal
old Java router
orignal
68 and 2 just lack of SSU2 routers
R4SAS
dropped logs and enabled transit on kyY2
zzz
I got a few more late acks on xZ9n
zzz
orignal, do you have logs to investigate?
orignal
no
orignal
what was the delay?
orignal
and tell me the time I will check
orignal
I see bunch of SSU2: Unexpected message type 14 from 81.7.18.46:16799
orignal
at 05:25
zzz
ok this is UTC + 2
zzz
00:15:47 I sent the message
zzz
00:15:48 retx
orignal
what was EST time?
zzz
00:15:51 retx
orignal
utc+2 is germany ))
zzz
00:15:54 retx
zzz
00:15:57 give up
orignal
no I don't see anything is the log
orignal
and when did you receive ack?
zzz
00:17:31 got acks of all 4
zzz
subtract 6 hours for EDT
zzz
I2NP message was 3186573505
zzz
type 11 size 262
zzz
00:17:31 got acks of all 4
orignal
only ack block?
zzz
don't know
orignal
I'm trying to understand what happens after a minte
zzz
pkt numbers 5, 6, 7, 8
orignal
looks like 1.5 minutes is consistent time
orignal
do you know if you recieved another data from me
orignal
*were receiving
zzz
doesn't look like I got anything between when I gave up and when I finally got the ack
zzz
let me know when you have the logging set up to catch it, and then I'll tell you when I get the next one
orignal
and there was not reconnect?
zzz
no. same session
orignal
let me think first what should I log
orignal
because there is no noticable problem on my side
orignal
also I want to see on i2pd side
orignal
R4SAS look for "SSU2: Packet was not Acked after
orignal
I think this ack is triggered by a tunnel test message
zzz
doesn't matter, anything could trigger it. question is why I didn't get the 4 acks right away
orignal
I'm trying to investigate why do you even get an ack
orignal
unrelate to this question
orignal
if we have both ipv4 and ipv6 firewalled
orignal
is it allowed to publish the same introducer in both?
zzz
hmm
zzz
I think so
orignal
great
orignal
I think this will be a usual way
orignal
back to delayed acks
orignal
do you know if it was a gap in packet num when you ahve received that delayed ack
R4SAS
<+orignal> R4SAS look for "SSU2: Packet was not Acked after
R4SAS
no such messages
orignal
that's what I'm wondering if it happens with Java only
orignal
myabe zzz somehow ignores my ack only packets
zzz
no I dont
orignal
would be nice to see packets gaps
orignal
we would know for sure if I don't send acks at all or they are lost on the way
zzz
I can look but this would be a lot easier if you were logging also
zzz
ok, found a nasty bug on my side, may not be the only problem though, but stand by until I can straighten this out
zzz
it's actually the opposite problem, treating nacks as acks, but it's screwing up my logs
zzz
ok, fixed. so if you're not acking, I'll see it more often now... we'll see...
R4SAS
I still can't find any "not Acked" messages
R4SAS
2Gb of logs...
R4SAS
dropping them
orignal
yes that's strange
orignal
zzz, is it possible to send relay tag request in SessionCreated?
zzz
why?
orignal
my ipv4 is firewalled, my ipv6 receive incoming conection
orignal
and I want that incoming ipv6 be an introducer for my ipv4 address
zzz
spec currently says:
zzz
Relay Tag Request
zzz
This may be sent by Alice in a Session Request, Session Confirmed, or Data message.
zzz
Blinded message
zzz
Blinded message
orignal
well, what if I send it in first Data message as Ack to SessionConfirmed?
zzz
in SSU 1 it was only a flag in session request
orignal
I know, but SSU2 is not SSU1
zzz
right, but that's why it 's unimplemented for me
orignal
I think we should have a way to set relay tag for incoming messages
zzz
the thing is, you don't know enough to request a tag in session created
zzz
you don't have his RI yet, so you don't know if he supports ipv4 and supports relay
orignal
agree, so after SessionCreated
orignal
*SessionConfirmed
zzz
right. spec says you can send in data phase, but it's unim[plemented for me, I just ignore it
zzz
if you start sending it let me know
orignal
fine
orignal
my point is deeper
orignal
any session might have two relay tags
orignal
in this case
zzz
well, the new one would replace the old one
zzz
right?
zzz
but why two?
orignal
incming session might want me to be an introducer for it
orignal
and I want this incoming session be an introducers for my another address
orignal
so a session is linked to two relay tags
orignal
for different puproses
zzz
I'm confused, I don't see how that would work
orignal
I'm Charlie for ipv4 and my ipv6 peer is Bob
orignal
at the same time I'm Bob for my peer in thier ipv6 and they are Charlie
orignal
e.g. I might recieve RelayIntro and RelayRequest
zzz
so both bob is an introducer for charlie and charlie is an introducer for bob?
orignal
yes
orignal
for different adddreses
zzz
that's allowed now. relay tags are "one direction only". So you can have a different one for the "other direction"
orignal
I don't have it yet
orignal
I assume single relay tag per session but will change it
zzz
I have different variables, even for SSU 1, even though only one was active:
zzz
private long _weRelayToThemAs;
zzz
private long _theyRelayToUsAs;
zzz
but yeah, with tag requests in data phase, now it's possible in SSU 2
orignal
will change
zzz
I'll add a note to the spec
orignal
SSU2 is more complex
orignal
because ipv4 and ipv6 can't be used in any combination
zzz
half an hour ago:
zzz
never got ack of session confirmed from xZ9n
zzz
07-10 21:47:52.143 DEBUG [acket pusher] outer.transport.udp.PeerState2: New data pkt 1 sent with 1 fragments on 5.183.32.144:13039 xZ9nsA OB2 recvAge: 0ms sendAge: 52y sendAttemptAge: 0ms sendACKAge: 0ms lifetime: 0ms RTT: 164 RTO: 1000 MTU: 1280 LMTU: 1500 cwin: 3840 acwin: 2890 SST: 524288 FRTX? false consecFail: 0 msgs rcvd: 0 msgs sent: 1 pkts rcvd OK/Dup: 0/0 pkts sent OK/Dup: 0/0 IBM: 0 OBQ: 0 OBL: 1
zzz
07-10 21:47:53.145 INFO [acket pusher] outer.transport.udp.PeerState2: ReTX Sess Conf on 5.183.32.144:13039 xZ9nsA OB2 recvAge: 1002ms sendAge: 52y sendAttemptAge: 1002ms sendACKAge: 1002ms lifetime: 1002ms RTT: 164 RTO: 1000 MTU: 1280 LMTU: 1500 cwin: 3840 acwin: 2890 SST: 524288 FRTX? false consecFail: 0 msgs rcvd: 0 msgs sent: 1 pkts rcvd OK/Dup: 0/0 pkts sent OK/Dup: 1/0 IBM: 0 OBQ: 0 OBL: 1
zzz
07-10 21:47:53.145 DEBUG [acket pusher] outer.transport.udp.PeerState2: New data pkt 2 sent with 1 fragments on 5.183.32.144:13039 xZ9nsA OB2 recvAge: 1002ms sendAge: 52y sendAttemptAge: 0ms sendACKAge: 0ms lifetime: 1002ms RTT: 164 RTO: 2000 MTU: 1280 LMTU: 1500 cwin: 1500 acwin: 2890 SST: 2560 FRTX? false consecFail: 0 msgs rcvd: 0 msgs sent: 1 pkts rcvd OK/Dup: 0/0 pkts sent OK/Dup: 1/1 IBM: 0 OBQ: 0 OBL: 1
zzz
07-10 21:47:54.145 INFO [acket pusher] outer.transport.udp.PeerState2: ReTX Sess Conf on 5.183.32.144:13039 xZ9nsA OB2 recvAge: 2002ms sendAge: 52y sendAttemptAge: 1000ms sendACKAge: 1000ms lifetime: 2002ms RTT: 164 RTO: 2000 MTU: 1280 LMTU: 1500 cwin: 1500 acwin: 2890 SST: 2560 FRTX? false consecFail: 0 msgs rcvd: 0 msgs sent: 1 pkts rcvd OK/Dup: 0/0 pkts sent OK/Dup: 2/1 IBM: 0 OBQ: 0 OBL: 1
zzz
07-10 21:47:55.145 DEBUG [acket pusher] outer.transport.udp.PeerState2: New data pkt 3 sent with 1 fragments on 5.183.32.144:13039 xZ9nsA OB2 recvAge: 3002ms sendAge: 52y sendAttemptAge: 0ms sendACKAge: 0ms lifetime: 3002ms RTT: 164 RTO: 4000 MTU: 1280 LMTU: 1500 cwin: 1500 acwin: 2890 SST: 2560 FRTX? false consecFail: 0 msgs rcvd: 0 msgs sent: 1 pkts rcvd OK/Dup: 0/0 pkts sent OK/Dup: 2/2 IBM: 0 OBQ: 0 OBL: 1
zzz
07-10 21:47:56.166 INFO [acket pusher] outer.transport.udp.PeerState2: ReTX Sess Conf on 5.183.32.144:13039 xZ9nsA OB2 recvAge: 4023ms sendAge: 52y sendAttemptAge: 1021ms sendACKAge: 1021ms lifetime: 4023ms RTT: 164 RTO: 4000 MTU: 1280 LMTU: 1500 cwin: 1500 acwin: 2890 SST: 2560 FRTX? false consecFail: 0 msgs rcvd: 0 msgs sent: 1 pkts rcvd OK/Dup: 0/0 pkts sent OK/Dup: 3/2 IBM: 0 OBQ: 0 OBL: 1
zzz
07-10 21:47:59.145 DEBUG [acket pusher] outer.transport.udp.PeerState2: New data pkt 4 sent with 1 fragments on 5.183.32.144:13039 xZ9nsA OB2 recvAge: 7s sendAge: 52y sendAttemptAge: 0ms sendACKAge: 0ms lifetime: 7s RTT: 164 RTO: 8000 MTU: 1280 LMTU: 1500 cwin: 1500 acwin: 2890 SST: 2560 FRTX? false consecFail: 0 msgs rcvd: 0 msgs sent: 1 pkts rcvd OK/Dup: 0/0 pkts sent OK/Dup: 3/3 IBM: 0 OBQ: 0 OBL: 1
zzz
07-10 21:48:00.177 INFO [acket pusher] outer.transport.udp.PeerState2: ReTX Sess Conf on 5.183.32.144:13039 xZ9nsA OB2 recvAge: 8s sendAge: 52y sendAttemptAge: 1032ms sendACKAge: 1032ms lifetime: 8s RTT: 164 RTO: 8000 MTU: 1280 LMTU: 1500 cwin: 1500 acwin: 2890 SST: 2560 FRTX? false consecFail: 0 msgs rcvd: 0 msgs sent: 1 pkts rcvd OK/Dup: 0/0 pkts sent OK/Dup: 4/3 IBM: 0 OBQ: 0 OBL: 1
zzz
07-10 21:48:02.170 WARN [acket pusher] outer.transport.udp.PeerState2: Message expired: OB Message 1096810328 seq 0 type 25 size 882 volleys: 4 lifetime: 10027 unacked to: 5.183.32.144:13039 xZ9nsA OB2 recvAge: 10s sendAge: 52y sendAttemptAge: 3025ms sendACKAge: 3025ms lifetime: 10s RTT: 164 RTO: 8000 MTU: 1280 LMTU: 1500 cwin: 1500 acwin: 2890 SST: 2560 FRTX? false consecFail: 1 msgs rcvd: 0 msgs sent: 1 pkts rcvd
zzz
OK/Dup: 0/0 pkts sent OK/Dup: 4/3 IBM: 0 OBQ: 0 OBL: 0
zzz
07-10 21:49:37.200 WARN [acket pusher] outer.transport.udp.PeerState2: Fail, no Sess Conf ACK rcvd on 5.183.32.144:13039 xZ9nsA OB2 recvAge: 105s sendAge: 52y sendAttemptAge: 0ms sendACKAge: 0ms lifetime: 105s RTT: 164 RTO: 8000 MTU: 1280 LMTU: 1500 cwin: 1500 acwin: 1356 SST: 2560 FRTX? false consecFail: 1 msgs rcvd: 0 msgs sent: 2 pkts rcvd OK/Dup: 0/0 pkts sent OK/Dup: 5/3 IBM: 0 OBQ: 0 OBL: 1
orignal
that's reasonable
orignal
I assume session is connected
orignal
and ignore your SessionConfirmed
orignal
need to improve the code
zzz
but I also sent 5 data packets, while I was retransmitting session confirmed, never got an ack for anything at all
orignal
you didn't receive Ack to first sessionconfirmed
zzz
correct. never got anything
orignal
and didn't receive anuthing else
orignal
maybe communication problem
zzz
msgs rcvd: 0 msgs sent: 2 pkts rcvd OK/Dup: 0/0 pkts sent OK/Dup: 5/3
zzz
please check logs
orignal
sec
orignal
15:47:52@458/warn - SSU2: Unexpected message type 206 from 81.7.18.46:16799
orignal
yours?
orignal
I see 3 messages like this and nothing else
orignal
it's clear they are SessionConfirmed
zzz
but I sent both, 4x: retx session confirmed, and a data packet
zzz
never got an ack of either
orignal
yes
orignal
I couln't decrypt retransmissions of SessionConfirmed
orignal
and hanled and acked data messages
zzz
never got any acks. I sent 5 data messages
orignal
that's what I mean
orignal
communication in that direction was broken
orignal
and we can't do too much with it
zzz
are you sure you sent the acks?
zzz
here's a strange ack behavior from i2pd:
zzz
after a "jump"
zzz
07-10 22:55:31.607 DEBUG [ handler 1/1] outer.transport.udp.PeerState2: Got new ACK block from 3PYq0v ACK 605-351 NACK 350-310 ACK 309-287 NACK 286-222 ACK 221-216 NACK 215 ACK 214 NACK 213-208 ACK 207 NACK 206 ACK 205 NACK 204 ACK 203 NACK 202 ACK 201 NACK 200 ACK 199 NACK 198 ACK 197 NACK 196 ACK 195 NACK 194 ACK 193 NACK 192 ACK 191 NACK 190 ACK 189-39 NACK 38-35 ACK 34 NACK 33-28 ACK 27 NACK 26-19 ACK 18 NACK 17
zzz
ACK 16 NACK 15 ACK 14 NACK 13 ACK 12 NACK 11 ACK 10-0
zzz
07-10 22:55:31.607 DEBUG [ handler 1/1] outer.transport.udp.PeerState2: Got new ACK block from 3PYq0v ACK 607
zzz
07-10 22:55:31.607 DEBUG [ handler 1/1] outer.transport.udp.PeerState2: Got new ACK block from 3PYq0v ACK 608
zzz
07-10 22:55:31.607 DEBUG [ handler 1/1] outer.transport.udp.PeerState2: Got new ACK block from 3PYq0v ACK 609
zzz
07-10 22:55:31.608 DEBUG [ handler 1/1] outer.transport.udp.PeerState2: Got new ACK block from 3PYq0v ACK 610
zzz
07-10 22:55:31.608 DEBUG [ handler 1/1] outer.transport.udp.PeerState2: Got new ACK block from 3PYq0v ACK 611
zzz
07-10 22:55:31.608 DEBUG [ handler 1/1] outer.transport.udp.PeerState2: Got new ACK block from 3PYq0v ACK 612
zzz
07-10 22:55:31.671 DEBUG [ handler 1/1] outer.transport.udp.PeerState2: Got new ACK block from 3PYq0v ACK 613-358
zzz
07-10 22:55:31.825 DEBUG [ handler 1/1] outer.transport.udp.PeerState2: Got new ACK block from 3PYq0v ACK 614-359
zzz
Note 607, ... 612 had acnt = 0, and 606 wasnn't acked until you acked 613
zzz
and then you had acnt > 0 again from then on
zzz
all legal, but strange
orignal
you means replacement of ranges by acnt?
orignal
I do it after 32 out of sequence packets
zzz
Got new ACK block from 3PYq0v ACK 607 <--- ack through 607, acnt 0
orignal
how about ranges?
zzz
I guess maybe you didn't get 606, and didn't have room for ranges? that's possible
zzz
no ranges
orignal
it's bug then
orignal
it acnt is zero without ranges it's bug
orignal
acnt can be zero only for 0 ack trough
orignal
otherwide it must be followed by ranges
orignal
I will check
zzz
ok. it was in a 377 byte packet, so you had plenty of room
orignal
it was not about room
zzz
right
orignal
acnt should be 255 in this case
zzz
I never got any ranges again (but maybe there weren't any more nacks)
zzz
last was
zzz
07-10 22:57:20.560 DEBUG [ handler 1/1] outer.transport.udp.PeerState2: Got new ACK block from 3PYq0v ACK 929-674
orignal
looks right
orignal
ok. so you are complaining about acks for individual messages?
orignal
tell me if it's valid or not
orignal
I know why I do it
orignal
if it's wrong I will change it
zzz
it's definitely valid
orignal
basically when I think I will never receive a missing packet
orignal
I start closing gaps one by one
orignal
to reduce number of ranges
orignal
and you are right, I shoudl set acnt to 255 in this case