View Issue Details

IDProjectCategoryView StatusLast Update
0003574GNUnetcadet servicepublic2018-06-07 00:25
ReporterChristian Grothoff Assigned ToBart Polot  
PriorityimmediateSeverityblockReproducibilityalways
Status closedResolutionfixed 
Product VersionGit master 
Target Version0.11.0pre66Fixed in Version0.11.0pre66 
Summary0003574: CADET fails to transmit message
DescriptionThere is a cadet issue, with "bob" sending multiple replies to Alice,
but after the first one CADET is stuck waiting for the ack.

This is in a situation where the used to be 2 channels, and 1 was
destroyed. Interesting bit as usual at the very end (where the test
hangs). Note that Bob is waiting for the ACK, and Alice *never
receives* the message.

Please fix ASAP!

-Christian

grothoff@spec:~/svn/gnunet/src/scalarproduct$ ./perf_scalarproduct.sh
Waiting for peers to start...
Running problem of size 400
Dec 11 23:07:56-071335 cadet-api-32318 DEBUG GNUNET_CADET_connect()
Dec 11 23:07:56-071385 cadet-api-32318 DEBUG addr 0x241d6b0
Dec 11 23:07:56-071438 cadet-api-32318 DEBUG port 20
Dec 11 23:07:56-071452 cadet-api-32318 DEBUG Sending 8 bytes long
message with 1 ports
Dec 11 23:07:56-071463 cadet-api-32318 DEBUG Sending message to
service: { LOCAL_CONNECT}
Dec 11 23:07:56-071476 cadet-api-32318 DEBUG queued
Dec 11 23:07:56-071484 cadet-api-32318 DEBUG calling ntfy tmt rdy for
8 bytes
Dec 11 23:07:56-071496 cadet-api-32318 DEBUG GNUNET_CADET_connect() END
Dec 11 23:07:56-071533 cadet-api-32318 DEBUG
Dec 11 23:07:56-071546 cadet-api-32318 DEBUG # Send packet() Buffer 8
Dec 11 23:07:56-071554 cadet-api-32318 DEBUG # message internal
Dec 11 23:07:56-071563 cadet-api-32318 DEBUG # cadet internal traffic,
type { LOCAL_CONNECT}
Dec 11 23:07:56-071572 cadet-api-32318 DEBUG # total size: 8
Dec 11 23:07:56-071581 cadet-api-32318 DEBUG # nothing left to transmit
Dec 11 23:07:56-071589 cadet-api-32318 DEBUG # start receiving from service
Dec 11 23:07:56-071599 cadet-api-32318 DEBUG # Send packet() END
Dec 11 23:07:56-071664 scalarproduct-bob-32318 DEBUG Creating new set
(operation 1)
Dec 11 23:07:56-076341 cadet-api-32320 DEBUG GNUNET_CADET_connect()
Dec 11 23:07:56-076390 cadet-api-32320 DEBUG addr 0x1b72180
Dec 11 23:07:56-076438 cadet-api-32320 DEBUG port 19
Dec 11 23:07:56-076455 cadet-api-32320 DEBUG Sending 8 bytes long
message with 1 ports
Dec 11 23:07:56-076469 cadet-api-32320 DEBUG Sending message to
service: { LOCAL_CONNECT}
Dec 11 23:07:56-076483 cadet-api-32320 DEBUG queued
Dec 11 23:07:56-076494 cadet-api-32320 DEBUG calling ntfy tmt rdy for
8 bytes
Dec 11 23:07:56-076512 cadet-api-32320 DEBUG GNUNET_CADET_connect() END
Dec 11 23:07:56-076550 cadet-api-32320 DEBUG
Dec 11 23:07:56-076565 cadet-api-32320 DEBUG # Send packet() Buffer 8
Dec 11 23:07:56-076577 cadet-api-32320 DEBUG # message internal
Dec 11 23:07:56-076590 cadet-api-32320 DEBUG # cadet internal traffic,
type { LOCAL_CONNECT}
Dec 11 23:07:56-076602 cadet-api-32320 DEBUG # total size: 8
Dec 11 23:07:56-076614 cadet-api-32320 DEBUG # nothing left to transmit
Dec 11 23:07:56-076624 cadet-api-32320 DEBUG # start receiving from service
Dec 11 23:07:56-076637 cadet-api-32320 DEBUG # Send packet() END
Establishing links. Please wait
..
2 links succeeded
0 links failed due to timeouts
Dec 11 23:07:57-259399 cadet-api-32317 DEBUG GNUNET_CADET_connect()
Dec 11 23:07:57-259456 cadet-api-32317 DEBUG addr 0x17ec360
Dec 11 23:07:57-259512 cadet-api-32317 DEBUG Sending 4 bytes long
message with 0 ports
Dec 11 23:07:57-259532 cadet-api-32317 DEBUG Sending message to
service: { LOCAL_CONNECT}
Dec 11 23:07:57-259549 cadet-api-32317 DEBUG queued
Dec 11 23:07:57-259566 cadet-api-32317 DEBUG calling ntfy tmt rdy for
4 bytes
Dec 11 23:07:57-259585 cadet-api-32317 DEBUG GNUNET_CADET_connect() END
Dec 11 23:07:57-259632 cadet-api-32317 DEBUG
Dec 11 23:07:57-259651 cadet-api-32317 DEBUG # Send packet() Buffer 4
Dec 11 23:07:57-259665 cadet-api-32317 DEBUG # message internal
Dec 11 23:07:57-259679 cadet-api-32317 DEBUG # cadet internal traffic,
type { LOCAL_CONNECT}
Dec 11 23:07:57-259694 cadet-api-32317 DEBUG # total size: 4
Dec 11 23:07:57-259709 cadet-api-32317 DEBUG # nothing left to transmit
Dec 11 23:07:57-259722 cadet-api-32317 DEBUG # start receiving from service
Dec 11 23:07:57-259740 cadet-api-32317 DEBUG # Send packet() END
Dec 11 23:07:57-259814 scalarproduct-alice-32317 DEBUG Creating new set
(operation 1)
Dec 11 23:07:57-260056 scalarproduct-alice-32317 DEBUG Creating new
channel for session with key QE66NDKW.
Dec 11 23:07:57-260081 cadet-api-32317 DEBUG Creating new channel to 6YNB:20
Dec 11 23:07:57-260092 cadet-api-32317 DEBUG at 0x181fec0
Dec 11 23:07:57-260100 cadet-api-32317 DEBUG number 80000000
Dec 11 23:07:57-260114 cadet-api-32317 DEBUG Sending message to
service: { CHANNEL_CREATE}
Dec 11 23:07:57-260123 cadet-api-32317 DEBUG queued
Dec 11 23:07:57-260131 cadet-api-32317 DEBUG calling ntfy tmt rdy for
48 bytes
Dec 11 23:07:57-260161 cadet-api-32317 DEBUG CADET NOTIFY TRANSMIT READY
Dec 11 23:07:57-260172 cadet-api-32317 DEBUG on channel 80000000
Dec 11 23:07:57-260181 cadet-api-32317 DEBUG allow_send 0
Dec 11 23:07:57-260189 cadet-api-32317 DEBUG to destination
Dec 11 23:07:57-260197 cadet-api-32317 DEBUG payload size 328
Dec 11 23:07:57-260205 cadet-api-32317 DEBUG total size 336
Dec 11 23:07:57-260226 cadet-api-32317 DEBUG
Dec 11 23:07:57-260236 cadet-api-32317 DEBUG # Send packet() Buffer 48
Dec 11 23:07:57-260244 cadet-api-32317 DEBUG # message internal
Dec 11 23:07:57-260251 cadet-api-32317 DEBUG # cadet internal traffic,
type { CHANNEL_CREATE}
Dec 11 23:07:57-260259 cadet-api-32317 DEBUG # total size: 48
Dec 11 23:07:57-260267 cadet-api-32317 DEBUG # can't transmit any more
Dec 11 23:07:57-260274 cadet-api-32317 DEBUG # Send packet() END
Dec 11 23:07:57-263378 cadet-api-32324 DEBUG GNUNET_CADET_connect()
Dec 11 23:07:57-263421 cadet-api-32324 DEBUG addr 0x1c64180
Dec 11 23:07:57-263469 cadet-api-32324 DEBUG port 19
Dec 11 23:07:57-263483 cadet-api-32324 DEBUG Sending 8 bytes long
message with 1 ports
Dec 11 23:07:57-263494 cadet-api-32324 DEBUG Sending message to
service: { LOCAL_CONNECT}
Dec 11 23:07:57-263504 cadet-api-32324 DEBUG queued
Dec 11 23:07:57-263513 cadet-api-32324 DEBUG calling ntfy tmt rdy for
8 bytes
Dec 11 23:07:57-263523 cadet-api-32324 DEBUG GNUNET_CADET_connect() END
Dec 11 23:07:57-263554 cadet-api-32324 DEBUG
Dec 11 23:07:57-263567 cadet-api-32324 DEBUG # Send packet() Buffer 8
Dec 11 23:07:57-263575 cadet-api-32324 DEBUG # message internal
Dec 11 23:07:57-263584 cadet-api-32324 DEBUG # cadet internal traffic,
type { LOCAL_CONNECT}
Dec 11 23:07:57-263593 cadet-api-32324 DEBUG # total size: 8
Dec 11 23:07:57-263601 cadet-api-32324 DEBUG # nothing left to transmit
Dec 11 23:07:57-263608 cadet-api-32324 DEBUG # start receiving from service
Dec 11 23:07:57-263617 cadet-api-32324 DEBUG # Send packet() END
Dec 11 23:07:57-461326 cadet-api-32318 DEBUG
Dec 11 23:07:57-461354 cadet-api-32318 DEBUG Received a message: {
CHANNEL_CREATE}
Dec 11 23:07:57-461363 cadet-api-32318 DEBUG Creating incoming channel
B0000000:20
Dec 11 23:07:57-461373 cadet-api-32318 DEBUG created channel 0x24390a0
Dec 11 23:07:57-461389 scalarproduct-bob-32318 DEBUG New incoming
channel from peer 6DEV.
Dec 11 23:07:57-461398 cadet-api-32318 DEBUG User notified
Dec 11 23:07:57-461403 cadet-api-32318 DEBUG message processed
Dec 11 23:07:57-462421 cadet-api-32317 DEBUG
Dec 11 23:07:57-462438 cadet-api-32317 DEBUG Received a message: {
   LOCAL_ACK}
Dec 11 23:07:57-462444 cadet-api-32317 DEBUG Got an ACK!
Dec 11 23:07:57-462449 cadet-api-32317 DEBUG on channel 80000000!
Dec 11 23:07:57-462454 cadet-api-32317 DEBUG tmt rdy was NULL, requesting!
Dec 11 23:07:57-462460 cadet-api-32317 DEBUG message processed
Dec 11 23:07:57-462473 cadet-api-32317 DEBUG
Dec 11 23:07:57-462481 cadet-api-32317 DEBUG # Send packet() Buffer 336
Dec 11 23:07:57-462490 cadet-api-32317 DEBUG # message payload ok
Dec 11 23:07:57-462499 cadet-api-32317 DEBUG # payload
Dec 11 23:07:57-462512 cadet-api-32317 DEBUG # payload type 644
(UNKNOWN TYPE)
Dec 11 23:07:57-462521 cadet-api-32317 DEBUG # total size: 336
Dec 11 23:07:57-462526 cadet-api-32317 DEBUG # nothing left to transmit
Dec 11 23:07:57-462529 cadet-api-32317 DEBUG # Send packet() END
Dec 11 23:07:57-462721 cadet-api-32317 DEBUG
Dec 11 23:07:57-462736 cadet-api-32317 DEBUG Received a message: {
   LOCAL_ACK}
Dec 11 23:07:57-462744 cadet-api-32317 DEBUG Got an ACK!
Dec 11 23:07:57-462750 cadet-api-32317 DEBUG on channel 80000000!
Dec 11 23:07:57-462756 cadet-api-32317 DEBUG message processed
Dec 11 23:07:57-463562 cadet-api-32318 DEBUG
Dec 11 23:07:57-463578 cadet-api-32318 DEBUG Received a message: {
   LOCAL_ACK}
Dec 11 23:07:57-463589 cadet-api-32318 DEBUG Got an ACK!
Dec 11 23:07:57-463598 cadet-api-32318 DEBUG on channel B0000000!
Dec 11 23:07:57-463603 cadet-api-32318 DEBUG message processed
Dec 11 23:07:57-464035 cadet-api-32318 DEBUG
Dec 11 23:07:57-464051 cadet-api-32318 DEBUG Received a message: {
  LOCAL_DATA}
Dec 11 23:07:57-464062 cadet-api-32318 DEBUG Got a data message!
Dec 11 23:07:57-464075 cadet-api-32318 DEBUG FWD data on channel 6DEV
[B0000000]
Dec 11 23:07:57-464082 cadet-api-32318 DEBUG 336 bytes
Dec 11 23:07:57-464087 cadet-api-32318 DEBUG payload type 644 (UNKNOWN
TYPE)
Dec 11 23:07:57-464091 cadet-api-32318 DEBUG checking handler for
type 644
Dec 11 23:07:57-464101 scalarproduct-bob-32318 DEBUG Got session with
key QE66NDKW and 404 elements, starting intersection.
Dec 11 23:07:57-464120 cadet-api-32318 DEBUG callback completed successfully
Dec 11 23:07:57-464125 cadet-api-32318 DEBUG message processed
Dec 11 23:07:57-464181 cadet-api-32320 DEBUG Creating new channel to 6DEV:19
Dec 11 23:07:57-464209 cadet-api-32320 DEBUG at 0x1b9c400
Dec 11 23:07:57-464221 cadet-api-32320 DEBUG number 80000000
Dec 11 23:07:57-464238 cadet-api-32320 DEBUG Sending message to
service: { CHANNEL_CREATE}
Dec 11 23:07:57-464250 cadet-api-32320 DEBUG queued
Dec 11 23:07:57-464260 cadet-api-32320 DEBUG calling ntfy tmt rdy for
48 bytes
Dec 11 23:07:57-464280 cadet-api-32320 DEBUG CADET NOTIFY TRANSMIT READY
Dec 11 23:07:57-464292 cadet-api-32320 DEBUG on channel 80000000
Dec 11 23:07:57-464303 cadet-api-32320 DEBUG allow_send 0
Dec 11 23:07:57-464315 cadet-api-32320 DEBUG to destination
Dec 11 23:07:57-464325 cadet-api-32320 DEBUG payload size 76
Dec 11 23:07:57-464337 cadet-api-32320 DEBUG total size 84
Dec 11 23:07:57-464358 cadet-api-32320 DEBUG
Dec 11 23:07:57-464371 cadet-api-32320 DEBUG # Send packet() Buffer 48
Dec 11 23:07:57-464381 cadet-api-32320 DEBUG # message internal
Dec 11 23:07:57-464392 cadet-api-32320 DEBUG # cadet internal traffic,
type { CHANNEL_CREATE}
Dec 11 23:07:57-464403 cadet-api-32320 DEBUG # total size: 48
Dec 11 23:07:57-464414 cadet-api-32320 DEBUG # can't transmit any more
Dec 11 23:07:57-464425 cadet-api-32320 DEBUG # Send packet() END
Dec 11 23:07:57-465984 cadet-api-32324 DEBUG
Dec 11 23:07:57-466007 cadet-api-32324 DEBUG Received a message: {
CHANNEL_CREATE}
Dec 11 23:07:57-466022 cadet-api-32324 DEBUG Creating incoming channel
B0000000:19
Dec 11 23:07:57-466044 cadet-api-32324 DEBUG created channel 0x1c83210
Dec 11 23:07:57-466064 cadet-api-32324 DEBUG User notified
Dec 11 23:07:57-466078 cadet-api-32324 DEBUG message processed
Dec 11 23:07:57-467256 cadet-api-32320 DEBUG
Dec 11 23:07:57-467274 cadet-api-32320 DEBUG Received a message: {
   LOCAL_ACK}
Dec 11 23:07:57-467282 cadet-api-32320 DEBUG Got an ACK!
Dec 11 23:07:57-467291 cadet-api-32320 DEBUG on channel 80000000!
Dec 11 23:07:57-467299 cadet-api-32320 DEBUG tmt rdy was NULL, requesting!
Dec 11 23:07:57-467308 cadet-api-32320 DEBUG message processed
Dec 11 23:07:57-467319 cadet-api-32320 DEBUG
Dec 11 23:07:57-467328 cadet-api-32320 DEBUG # Send packet() Buffer 84
Dec 11 23:07:57-467336 cadet-api-32320 DEBUG # message payload ok
Dec 11 23:07:57-467343 cadet-api-32320 DEBUG # payload
Dec 11 23:07:57-467353 cadet-api-32320 DEBUG # payload type 581
(UNKNOWN TYPE)
Dec 11 23:07:57-467361 cadet-api-32320 DEBUG # total size: 84
Dec 11 23:07:57-467367 cadet-api-32320 DEBUG # nothing left to transmit
Dec 11 23:07:57-467374 cadet-api-32320 DEBUG # Send packet() END
Dec 11 23:07:57-467623 cadet-api-32320 DEBUG
Dec 11 23:07:57-467643 cadet-api-32320 DEBUG Received a message: {
   LOCAL_ACK}
Dec 11 23:07:57-467655 cadet-api-32320 DEBUG Got an ACK!
Dec 11 23:07:57-467665 cadet-api-32320 DEBUG on channel 80000000!
Dec 11 23:07:57-467677 cadet-api-32320 DEBUG message processed
Dec 11 23:07:57-468347 cadet-api-32324 DEBUG
Dec 11 23:07:57-468369 cadet-api-32324 DEBUG Received a message: {
   LOCAL_ACK}
Dec 11 23:07:57-468386 cadet-api-32324 DEBUG Got an ACK!
Dec 11 23:07:57-468397 cadet-api-32324 DEBUG on channel B0000000!
Dec 11 23:07:57-468404 cadet-api-32324 DEBUG message processed
Dec 11 23:07:57-469730 cadet-api-32324 DEBUG
Dec 11 23:07:57-469751 cadet-api-32324 DEBUG Received a message: {
  LOCAL_DATA}
Dec 11 23:07:57-469768 cadet-api-32324 DEBUG Got a data message!
Dec 11 23:07:57-469789 cadet-api-32324 DEBUG FWD data on channel 6YNB
[B0000000]
Dec 11 23:07:57-469798 cadet-api-32324 DEBUG 84 bytes
Dec 11 23:07:57-469807 cadet-api-32324 DEBUG payload type 581 (UNKNOWN
TYPE)
Dec 11 23:07:57-469814 cadet-api-32324 DEBUG checking handler for
type 581
Dec 11 23:07:57-469824 cadet-api-32324 DEBUG Sending ACK on channel B0000000
Dec 11 23:07:57-469831 cadet-api-32324 DEBUG Sending message to
service: { LOCAL_ACK}
Dec 11 23:07:57-469839 cadet-api-32324 DEBUG queued
Dec 11 23:07:57-469845 cadet-api-32324 DEBUG calling ntfy tmt rdy for
8 bytes
Dec 11 23:07:57-469866 cadet-api-32324 DEBUG callback completed successfully
Dec 11 23:07:57-469875 cadet-api-32324 DEBUG message processed
Dec 11 23:07:57-469887 cadet-api-32324 DEBUG
Dec 11 23:07:57-469895 cadet-api-32324 DEBUG # Send packet() Buffer 8
Dec 11 23:07:57-469902 cadet-api-32324 DEBUG # message internal
Dec 11 23:07:57-469909 cadet-api-32324 DEBUG # cadet internal traffic,
type { LOCAL_ACK}
Dec 11 23:07:57-469916 cadet-api-32324 DEBUG # total size: 8
Dec 11 23:07:57-469923 cadet-api-32324 DEBUG # nothing left to transmit
Dec 11 23:07:57-469929 cadet-api-32324 DEBUG # Send packet() END
Dec 11 23:07:57-472697 cadet-api-32324 DEBUG CADET NOTIFY TRANSMIT READY
Dec 11 23:07:57-472718 cadet-api-32324 DEBUG on channel B0000000
Dec 11 23:07:57-472727 cadet-api-32324 DEBUG allow_send 1
Dec 11 23:07:57-472734 cadet-api-32324 DEBUG to origin
Dec 11 23:07:57-472741 cadet-api-32324 DEBUG payload size 1250
Dec 11 23:07:57-472750 cadet-api-32324 DEBUG total size 1258
Dec 11 23:07:57-472758 cadet-api-32324 DEBUG call client notify tmt rdy
Dec 11 23:07:57-472767 cadet-api-32324 DEBUG CADET NOTIFY TRANSMIT READY END
Dec 11 23:07:57-472793 cadet-api-32324 DEBUG
Dec 11 23:07:57-472804 cadet-api-32324 DEBUG # Send packet() Buffer 1258
Dec 11 23:07:57-472812 cadet-api-32324 DEBUG # message payload ok
Dec 11 23:07:57-472819 cadet-api-32324 DEBUG # payload
Dec 11 23:07:57-472829 cadet-api-32324 DEBUG # payload type 592
(UNKNOWN TYPE)
Dec 11 23:07:57-472837 cadet-api-32324 DEBUG # total size: 1258
Dec 11 23:07:57-472844 cadet-api-32324 DEBUG # nothing left to transmit
Dec 11 23:07:57-472850 cadet-api-32324 DEBUG # Send packet() END
Dec 11 23:07:57-473083 cadet-api-32324 DEBUG
Dec 11 23:07:57-473095 cadet-api-32324 DEBUG Received a message: {
   LOCAL_ACK}
Dec 11 23:07:57-473102 cadet-api-32324 DEBUG Got an ACK!
Dec 11 23:07:57-473109 cadet-api-32324 DEBUG on channel B0000000!
Dec 11 23:07:57-473116 cadet-api-32324 DEBUG message processed
Dec 11 23:07:57-474134 cadet-api-32320 DEBUG
Dec 11 23:07:57-474156 cadet-api-32320 DEBUG Received a message: {
  LOCAL_DATA}
Dec 11 23:07:57-474172 cadet-api-32320 DEBUG Got a data message!
Dec 11 23:07:57-474189 cadet-api-32320 DEBUG BCK data on channel 6DEV
[80000000]
Dec 11 23:07:57-474203 cadet-api-32320 DEBUG 1258 bytes
Dec 11 23:07:57-474215 cadet-api-32320 DEBUG payload type 592 (UNKNOWN
TYPE)
Dec 11 23:07:57-474227 cadet-api-32320 DEBUG checking handler for
type 581
Dec 11 23:07:57-474237 cadet-api-32320 DEBUG checking handler for
type 583
Dec 11 23:07:57-474247 cadet-api-32320 DEBUG checking handler for
type 584
Dec 11 23:07:57-474257 cadet-api-32320 DEBUG checking handler for
type 586
Dec 11 23:07:57-474267 cadet-api-32320 DEBUG checking handler for
type 585
Dec 11 23:07:57-474366 cadet-api-32320 DEBUG checking handler for
type 582
Dec 11 23:07:57-474378 cadet-api-32320 DEBUG checking handler for
type 591
Dec 11 23:07:57-474389 cadet-api-32320 DEBUG checking handler for
type 592
Dec 11 23:07:57-474404 cadet-api-32320 DEBUG Sending ACK on channel 80000000
Dec 11 23:07:57-474415 cadet-api-32320 DEBUG Sending message to
service: { LOCAL_ACK}
Dec 11 23:07:57-474426 cadet-api-32320 DEBUG queued
Dec 11 23:07:57-474438 cadet-api-32320 DEBUG calling ntfy tmt rdy for
8 bytes
Dec 11 23:07:57-479665 cadet-api-32320 DEBUG CADET NOTIFY TRANSMIT READY
Dec 11 23:07:57-479683 cadet-api-32320 DEBUG on channel 80000000
Dec 11 23:07:57-479695 cadet-api-32320 DEBUG allow_send 1
Dec 11 23:07:57-479708 cadet-api-32320 DEBUG to destination
Dec 11 23:07:57-479720 cadet-api-32320 DEBUG payload size 1829
Dec 11 23:07:57-479733 cadet-api-32320 DEBUG total size 1837
Dec 11 23:07:57-479753 cadet-api-32320 DEBUG callback completed successfully
Dec 11 23:07:57-479768 cadet-api-32320 DEBUG message processed
Dec 11 23:07:57-479789 cadet-api-32320 DEBUG
Dec 11 23:07:57-479805 cadet-api-32320 DEBUG # Send packet() Buffer 84
Dec 11 23:07:57-479818 cadet-api-32320 DEBUG # message internal
Dec 11 23:07:57-479834 cadet-api-32320 DEBUG # cadet internal traffic,
type { LOCAL_ACK}
Dec 11 23:07:57-479848 cadet-api-32320 DEBUG # message payload ok
Dec 11 23:07:57-479860 cadet-api-32320 DEBUG # total size: 8
Dec 11 23:07:57-479872 cadet-api-32320 DEBUG # message payload ok
Dec 11 23:07:57-479887 cadet-api-32320 DEBUG # next size: 1837
Dec 11 23:07:57-479901 cadet-api-32320 DEBUG # Send packet() END
Dec 11 23:07:57-479933 cadet-api-32320 DEBUG
Dec 11 23:07:57-479951 cadet-api-32320 DEBUG # Send packet() Buffer 1837
Dec 11 23:07:57-479963 cadet-api-32320 DEBUG # message payload ok
Dec 11 23:07:57-479975 cadet-api-32320 DEBUG # payload
Dec 11 23:07:57-479991 cadet-api-32320 DEBUG # payload type 592
(UNKNOWN TYPE)
Dec 11 23:07:57-480002 cadet-api-32320 DEBUG # total size: 1837
Dec 11 23:07:57-479995 scalarproduct-bob-32318 DEBUG Removed element
with key E7PW0RHK and value 10
Dec 11 23:07:57-480012 cadet-api-32320 DEBUG # nothing left to transmit
Dec 11 23:07:57-480017 cadet-api-32320 DEBUG # Send packet() END
Dec 11 23:07:57-480308 cadet-api-32320 DEBUG
Dec 11 23:07:57-480326 cadet-api-32320 DEBUG Received a message: {
   LOCAL_ACK}
Dec 11 23:07:57-480340 cadet-api-32320 DEBUG Got an ACK!
Dec 11 23:07:57-480353 cadet-api-32320 DEBUG on channel 80000000!
Dec 11 23:07:57-480361 cadet-api-32320 DEBUG message processed
Dec 11 23:07:57-481307 cadet-api-32324 DEBUG
Dec 11 23:07:57-481328 cadet-api-32324 DEBUG Received a message: {
  LOCAL_DATA}
Dec 11 23:07:57-481343 cadet-api-32324 DEBUG Got a data message!
Dec 11 23:07:57-481356 cadet-api-32324 DEBUG FWD data on channel 6YNB
[B0000000]
Dec 11 23:07:57-481364 cadet-api-32324 DEBUG 1837 bytes
Dec 11 23:07:57-481371 cadet-api-32324 DEBUG payload type 592 (UNKNOWN
TYPE)
Dec 11 23:07:57-481378 cadet-api-32324 DEBUG checking handler for
type 581
Dec 11 23:07:57-481384 cadet-api-32324 DEBUG checking handler for
type 583
Dec 11 23:07:57-481391 cadet-api-32324 DEBUG checking handler for
type 584
Dec 11 23:07:57-481397 cadet-api-32324 DEBUG checking handler for
type 586
Dec 11 23:07:57-481404 cadet-api-32324 DEBUG checking handler for
type 585
Dec 11 23:07:57-481411 cadet-api-32324 DEBUG checking handler for
type 582
Dec 11 23:07:57-481417 cadet-api-32324 DEBUG checking handler for
type 591
Dec 11 23:07:57-481424 cadet-api-32324 DEBUG checking handler for
type 592
Dec 11 23:07:57-481431 cadet-api-32324 DEBUG Sending ACK on channel B0000000
Dec 11 23:07:57-481438 cadet-api-32324 DEBUG Sending message to
service: { LOCAL_ACK}
Dec 11 23:07:57-481445 cadet-api-32324 DEBUG queued
Dec 11 23:07:57-481452 cadet-api-32324 DEBUG calling ntfy tmt rdy for
8 bytes
Dec 11 23:07:57-483920 cadet-api-32324 DEBUG CADET NOTIFY TRANSMIT READY
Dec 11 23:07:57-483934 cadet-api-32324 DEBUG on channel B0000000
Dec 11 23:07:57-483941 cadet-api-32324 DEBUG allow_send 1
Dec 11 23:07:57-483948 cadet-api-32324 DEBUG to origin
Dec 11 23:07:57-483954 cadet-api-32324 DEBUG payload size 72
Dec 11 23:07:57-483961 cadet-api-32324 DEBUG total size 80
Dec 11 23:07:57-483969 cadet-api-32324 DEBUG callback completed successfully
Dec 11 23:07:57-483975 cadet-api-32324 DEBUG message processed
Dec 11 23:07:57-483988 cadet-api-32324 DEBUG
Dec 11 23:07:57-483996 cadet-api-32324 DEBUG # Send packet() Buffer 1258
Dec 11 23:07:57-484003 cadet-api-32324 DEBUG # message internal
Dec 11 23:07:57-484010 cadet-api-32324 DEBUG # cadet internal traffic,
type { LOCAL_ACK}
Dec 11 23:07:57-484018 cadet-api-32324 DEBUG # message payload ok
Dec 11 23:07:57-484024 cadet-api-32324 DEBUG # payload
Dec 11 23:07:57-484032 cadet-api-32324 DEBUG # payload type 593
(UNKNOWN TYPE)
Dec 11 23:07:57-484040 cadet-api-32324 DEBUG # total size: 88
Dec 11 23:07:57-484046 cadet-api-32324 DEBUG # nothing left to transmit
Dec 11 23:07:57-484053 cadet-api-32324 DEBUG # Send packet() END
Dec 11 23:07:57-484135 scalarproduct-alice-32317 DEBUG Intersection
removed element with key CBVGDJDA and value -20000
Dec 11 23:07:57-484387 cadet-api-32324 DEBUG
Dec 11 23:07:57-484409 cadet-api-32324 DEBUG Received a message: {
   LOCAL_ACK}
Dec 11 23:07:57-484424 cadet-api-32324 DEBUG Got an ACK!
Dec 11 23:07:57-484434 cadet-api-32324 DEBUG on channel B0000000!
Dec 11 23:07:57-484441 cadet-api-32324 DEBUG message processed
Dec 11 23:07:57-485492 cadet-api-32320 DEBUG
Dec 11 23:07:57-485514 cadet-api-32320 DEBUG Received a message: {
  LOCAL_DATA}
Dec 11 23:07:57-485529 cadet-api-32320 DEBUG Got a data message!
Dec 11 23:07:57-485543 cadet-api-32320 DEBUG BCK data on channel 6DEV
[80000000]
Dec 11 23:07:57-485551 cadet-api-32320 DEBUG 80 bytes
Dec 11 23:07:57-485558 cadet-api-32320 DEBUG payload type 593 (UNKNOWN
TYPE)
Dec 11 23:07:57-485565 cadet-api-32320 DEBUG checking handler for
type 581
Dec 11 23:07:57-485571 cadet-api-32320 DEBUG checking handler for
type 583
Dec 11 23:07:57-485578 cadet-api-32320 DEBUG checking handler for
type 584
Dec 11 23:07:57-485584 cadet-api-32320 DEBUG checking handler for
type 586
Dec 11 23:07:57-485591 cadet-api-32320 DEBUG checking handler for
type 585
Dec 11 23:07:57-485597 cadet-api-32320 DEBUG checking handler for
type 582
Dec 11 23:07:57-485604 cadet-api-32320 DEBUG checking handler for
type 591
Dec 11 23:07:57-485611 cadet-api-32320 DEBUG checking handler for
type 592
Dec 11 23:07:57-485617 cadet-api-32320 DEBUG checking handler for
type 593
Dec 11 23:07:57-485624 cadet-api-32320 DEBUG Sending ACK on channel 80000000
Dec 11 23:07:57-485631 cadet-api-32320 DEBUG Sending message to
service: { LOCAL_ACK}
Dec 11 23:07:57-485639 cadet-api-32320 DEBUG queued
Dec 11 23:07:57-485645 cadet-api-32320 DEBUG calling ntfy tmt rdy for
8 bytes
Dec 11 23:07:57-485693 cadet-api-32320 DEBUG Destroying channel
Dec 11 23:07:57-485705 cadet-api-32320 DEBUG destroy_channel 80000000
Dec 11 23:07:57-485713 cadet-api-32320 DEBUG calling cleaner
Dec 11 23:07:57-485725 cadet-api-32320 DEBUG Sending message to
service: { CHANNEL_DESTROY}
Dec 11 23:07:57-485733 cadet-api-32320 DEBUG queued
Dec 11 23:07:57-485739 cadet-api-32320 DEBUG calling ntfy tmt rdy for
48 bytes
Dec 11 23:07:57-485766 cadet-api-32320 DEBUG callback completed successfully
Dec 11 23:07:57-485774 cadet-api-32320 DEBUG message processed
Dec 11 23:07:57-485792 cadet-api-32320 DEBUG
Dec 11 23:07:57-485805 cadet-api-32320 DEBUG # Send packet() Buffer 1837
Dec 11 23:07:57-485818 cadet-api-32320 DEBUG # message internal
Dec 11 23:07:57-485830 cadet-api-32320 DEBUG # cadet internal traffic,
type { CHANNEL_DESTROY}
Dec 11 23:07:57-485830 cadet-api-32318 DEBUG Sending ACK on channel B0000000
Dec 11 23:07:57-485842 cadet-api-32320 DEBUG # total size: 48
Dec 11 23:07:57-485844 cadet-api-32318 DEBUG Sending message to
service: { LOCAL_ACK}
Dec 11 23:07:57-485849 cadet-api-32320 DEBUG # nothing left to transmit
Dec 11 23:07:57-485852 cadet-api-32318 DEBUG queued
Dec 11 23:07:57-485855 cadet-api-32320 DEBUG # Send packet() END
Dec 11 23:07:57-485858 cadet-api-32318 DEBUG calling ntfy tmt rdy for
8 bytes
Dec 11 23:07:57-485870 scalarproduct-bob-32318 DEBUG Finished
intersection, 403 items remain
Dec 11 23:07:57-485883 cadet-api-32318 DEBUG
Dec 11 23:07:57-485890 cadet-api-32318 DEBUG # Send packet() Buffer 8
Dec 11 23:07:57-485895 cadet-api-32318 DEBUG # message internal
Dec 11 23:07:57-485902 cadet-api-32318 DEBUG # cadet internal traffic,
type { LOCAL_ACK}
Dec 11 23:07:57-485909 cadet-api-32318 DEBUG # total size: 8
Dec 11 23:07:57-485915 cadet-api-32318 DEBUG # nothing left to transmit
Dec 11 23:07:57-485920 cadet-api-32318 DEBUG # Send packet() END
Dec 11 23:07:57-486905 cadet-api-32324 DEBUG
Dec 11 23:07:57-486927 cadet-api-32324 DEBUG Received a message: {
CHANNEL_DESTROY}
Dec 11 23:07:57-486941 cadet-api-32324 DEBUG Channel Destroy received
from service
Dec 11 23:07:57-486949 cadet-api-32324 DEBUG destroying channel B0000000
Dec 11 23:07:57-486959 cadet-api-32324 DEBUG destroy_channel B0000000
Dec 11 23:07:57-486973 cadet-api-32324 DEBUG calling cleaner
Dec 11 23:07:57-487065 cadet-api-32324 DEBUG message processed
Dec 11 23:07:57-487251 scalarproduct-alice-32317 DEBUG Finished
intersection, 403 items remain
Dec 11 23:07:57-487397 scalarproduct-alice-32317 DEBUG Sending 124/403
crypto values to Bob
Dec 11 23:08:05-559695 cadet-api-32317 DEBUG CADET NOTIFY TRANSMIT READY
Dec 11 23:08:05-559724 cadet-api-32317 DEBUG on channel 80000000
Dec 11 23:08:05-559733 cadet-api-32317 DEBUG allow_send 1
Dec 11 23:08:05-559740 cadet-api-32317 DEBUG to destination
Dec 11 23:08:05-559747 cadet-api-32317 DEBUG payload size 63992
Dec 11 23:08:05-559755 cadet-api-32317 DEBUG total size 64000
Dec 11 23:08:05-559767 cadet-api-32317 DEBUG call client notify tmt rdy
Dec 11 23:08:05-559778 cadet-api-32317 DEBUG CADET NOTIFY TRANSMIT READY END
Dec 11 23:08:05-559787 scalarproduct-alice-32317 DEBUG Sending 124/403
crypto values to Bob
Dec 11 23:08:13-625121 scalarproduct-alice-32317 DEBUG Sending 124/403
crypto values to Bob
Dec 11 23:08:21-698781 scalarproduct-alice-32317 DEBUG Sending 31/403
crypto values to Bob
Dec 11 23:08:23-714555 cadet-api-32317 DEBUG
Dec 11 23:08:23-714572 cadet-api-32317 DEBUG # Send packet() Buffer 64000
Dec 11 23:08:23-714581 cadet-api-32317 DEBUG # message payload ok
Dec 11 23:08:23-714588 cadet-api-32317 DEBUG # payload
Dec 11 23:08:23-714618 cadet-api-32317 DEBUG # payload type 645
(UNKNOWN TYPE)
Dec 11 23:08:23-714629 cadet-api-32317 DEBUG # total size: 64000
Dec 11 23:08:23-714636 cadet-api-32317 DEBUG # nothing left to transmit
Dec 11 23:08:23-714643 cadet-api-32317 DEBUG # Send packet() END
Dec 11 23:08:23-714670 cadet-api-32317 DEBUG CADET NOTIFY TRANSMIT READY
Dec 11 23:08:23-714688 cadet-api-32317 DEBUG on channel 80000000
Dec 11 23:08:23-714700 cadet-api-32317 DEBUG allow_send 0
Dec 11 23:08:23-714711 cadet-api-32317 DEBUG to destination
Dec 11 23:08:23-714723 cadet-api-32317 DEBUG payload size 63992
Dec 11 23:08:23-714735 cadet-api-32317 DEBUG total size 64000
Dec 11 23:08:23-716034 cadet-api-32317 DEBUG
Dec 11 23:08:23-716053 cadet-api-32317 DEBUG Received a message: {
   LOCAL_ACK}
Dec 11 23:08:23-716062 cadet-api-32317 DEBUG Got an ACK!
Dec 11 23:08:23-716070 cadet-api-32317 DEBUG on channel 80000000!
Dec 11 23:08:23-716077 cadet-api-32317 DEBUG tmt rdy was NULL, requesting!
Dec 11 23:08:23-716085 cadet-api-32317 DEBUG message processed
Dec 11 23:08:23-716097 cadet-api-32317 DEBUG
Dec 11 23:08:23-716105 cadet-api-32317 DEBUG # Send packet() Buffer 64000
Dec 11 23:08:23-716112 cadet-api-32317 DEBUG # message payload ok
Dec 11 23:08:23-716119 cadet-api-32317 DEBUG # payload
Dec 11 23:08:23-716143 cadet-api-32317 DEBUG # payload type 645
(UNKNOWN TYPE)
Dec 11 23:08:23-716161 cadet-api-32317 DEBUG # total size: 64000
Dec 11 23:08:23-716175 cadet-api-32317 DEBUG # nothing left to transmit
Dec 11 23:08:23-716189 cadet-api-32317 DEBUG # Send packet() END
Dec 11 23:08:23-716217 cadet-api-32317 DEBUG CADET NOTIFY TRANSMIT READY
Dec 11 23:08:23-716233 cadet-api-32317 DEBUG on channel 80000000
Dec 11 23:08:23-716247 cadet-api-32317 DEBUG allow_send 0
Dec 11 23:08:23-716262 cadet-api-32317 DEBUG to destination
Dec 11 23:08:23-716280 cadet-api-32317 DEBUG payload size 63992
Dec 11 23:08:23-716297 cadet-api-32317 DEBUG total size 64000
Dec 11 23:08:23-717476 cadet-api-32317 DEBUG
Dec 11 23:08:23-717495 cadet-api-32317 DEBUG Received a message: {
   LOCAL_ACK}
Dec 11 23:08:23-717503 cadet-api-32317 DEBUG Got an ACK!
Dec 11 23:08:23-717510 cadet-api-32317 DEBUG on channel 80000000!
Dec 11 23:08:23-717517 cadet-api-32317 DEBUG tmt rdy was NULL, requesting!
Dec 11 23:08:23-717525 cadet-api-32317 DEBUG message processed
Dec 11 23:08:23-717537 cadet-api-32317 DEBUG
Dec 11 23:08:23-717545 cadet-api-32317 DEBUG # Send packet() Buffer 64000
Dec 11 23:08:23-717552 cadet-api-32317 DEBUG # message payload ok
Dec 11 23:08:23-717558 cadet-api-32317 DEBUG # payload
Dec 11 23:08:23-717577 cadet-api-32317 DEBUG # payload type 645
(UNKNOWN TYPE)
Dec 11 23:08:23-717588 cadet-api-32317 DEBUG # total size: 64000
Dec 11 23:08:23-717596 cadet-api-32317 DEBUG # nothing left to transmit
Dec 11 23:08:23-717602 cadet-api-32317 DEBUG # Send packet() END
Dec 11 23:08:23-717629 cadet-api-32317 DEBUG CADET NOTIFY TRANSMIT READY
Dec 11 23:08:23-717650 cadet-api-32317 DEBUG on channel 80000000
Dec 11 23:08:23-717667 cadet-api-32317 DEBUG allow_send 0
Dec 11 23:08:23-717684 cadet-api-32317 DEBUG to destination
Dec 11 23:08:23-717699 cadet-api-32317 DEBUG payload size 16004
Dec 11 23:08:23-717711 cadet-api-32317 DEBUG total size 16012
Dec 11 23:08:23-718897 cadet-api-32317 DEBUG
Dec 11 23:08:23-718919 cadet-api-32317 DEBUG Received a message: {
   LOCAL_ACK}
Dec 11 23:08:23-718932 cadet-api-32317 DEBUG Got an ACK!
Dec 11 23:08:23-718945 cadet-api-32317 DEBUG on channel 80000000!
Dec 11 23:08:23-718959 cadet-api-32317 DEBUG tmt rdy was NULL, requesting!
Dec 11 23:08:23-718976 cadet-api-32317 DEBUG message processed
Dec 11 23:08:23-718990 cadet-api-32317 DEBUG
Dec 11 23:08:23-718999 cadet-api-32317 DEBUG # Send packet() Buffer 64000
Dec 11 23:08:23-719006 cadet-api-32317 DEBUG # message payload ok
Dec 11 23:08:23-719013 cadet-api-32317 DEBUG # payload
Dec 11 23:08:23-719026 cadet-api-32317 DEBUG # payload type 645
(UNKNOWN TYPE)
Dec 11 23:08:23-719043 cadet-api-32317 DEBUG # total size: 16012
Dec 11 23:08:23-719053 cadet-api-32317 DEBUG # nothing left to transmit
Dec 11 23:08:23-719059 cadet-api-32317 DEBUG # Send packet() END
Dec 11 23:08:23-719511 cadet-api-32317 DEBUG
Dec 11 23:08:23-719526 cadet-api-32317 DEBUG Received a message: {
   LOCAL_ACK}
Dec 11 23:08:23-719533 cadet-api-32317 DEBUG Got an ACK!
Dec 11 23:08:23-719540 cadet-api-32317 DEBUG on channel 80000000!
Dec 11 23:08:23-719547 cadet-api-32317 DEBUG message processed
Dec 11 23:08:23-721517 cadet-api-32318 DEBUG
Dec 11 23:08:23-721534 cadet-api-32318 DEBUG Received a message: {
  LOCAL_DATA}
Dec 11 23:08:23-721539 cadet-api-32318 DEBUG Got a data message!
Dec 11 23:08:23-721547 cadet-api-32318 DEBUG FWD data on channel 6DEV
[B0000000]
Dec 11 23:08:23-721551 cadet-api-32318 DEBUG 64000 bytes
Dec 11 23:08:23-721555 cadet-api-32318 DEBUG payload type 645 (UNKNOWN
TYPE)
Dec 11 23:08:23-721559 cadet-api-32318 DEBUG checking handler for
type 644
Dec 11 23:08:23-721562 cadet-api-32318 DEBUG checking handler for
type 645
Dec 11 23:08:23-721571 scalarproduct-bob-32318 DEBUG Received 124 crypto
values from Alice
Dec 11 23:08:23-721641 cadet-api-32318 DEBUG Sending ACK on channel B0000000
Dec 11 23:08:23-721649 cadet-api-32318 DEBUG Sending message to
service: { LOCAL_ACK}
Dec 11 23:08:23-721653 cadet-api-32318 DEBUG queued
Dec 11 23:08:23-721657 cadet-api-32318 DEBUG calling ntfy tmt rdy for
8 bytes
Dec 11 23:08:23-721662 cadet-api-32318 DEBUG callback completed successfully
Dec 11 23:08:23-721666 cadet-api-32318 DEBUG message processed
Dec 11 23:08:23-721675 cadet-api-32318 DEBUG
Dec 11 23:08:23-721679 cadet-api-32318 DEBUG # Send packet() Buffer 8
Dec 11 23:08:23-721683 cadet-api-32318 DEBUG # message internal
Dec 11 23:08:23-721687 cadet-api-32318 DEBUG # cadet internal traffic,
type { LOCAL_ACK}
Dec 11 23:08:23-721691 cadet-api-32318 DEBUG # total size: 8
Dec 11 23:08:23-721695 cadet-api-32318 DEBUG # nothing left to transmit
Dec 11 23:08:23-721699 cadet-api-32318 DEBUG # Send packet() END
Dec 11 23:08:23-723754 cadet-api-32318 DEBUG
Dec 11 23:08:23-723769 cadet-api-32318 DEBUG Received a message: {
  LOCAL_DATA}
Dec 11 23:08:23-723778 cadet-api-32318 DEBUG Got a data message!
Dec 11 23:08:23-723785 cadet-api-32318 DEBUG FWD data on channel 6DEV
[B0000000]
Dec 11 23:08:23-723790 cadet-api-32318 DEBUG 64000 bytes
Dec 11 23:08:23-723794 cadet-api-32318 DEBUG payload type 645 (UNKNOWN
TYPE)
Dec 11 23:08:23-723797 cadet-api-32318 DEBUG checking handler for
type 644
Dec 11 23:08:23-723801 cadet-api-32318 DEBUG checking handler for
type 645
Dec 11 23:08:23-723805 scalarproduct-bob-32318 DEBUG Received 124 crypto
values from Alice
Dec 11 23:08:23-723814 cadet-api-32318 DEBUG Sending ACK on channel B0000000
Dec 11 23:08:23-723819 cadet-api-32318 DEBUG Sending message to
service: { LOCAL_ACK}
Dec 11 23:08:23-723823 cadet-api-32318 DEBUG queued
Dec 11 23:08:23-723827 cadet-api-32318 DEBUG calling ntfy tmt rdy for
8 bytes
Dec 11 23:08:23-723832 cadet-api-32318 DEBUG callback completed successfully
Dec 11 23:08:23-723836 cadet-api-32318 DEBUG message processed
Dec 11 23:08:23-723844 cadet-api-32318 DEBUG
Dec 11 23:08:23-723849 cadet-api-32318 DEBUG # Send packet() Buffer 8
Dec 11 23:08:23-723852 cadet-api-32318 DEBUG # message internal
Dec 11 23:08:23-723856 cadet-api-32318 DEBUG # cadet internal traffic,
type { LOCAL_ACK}
Dec 11 23:08:23-723860 cadet-api-32318 DEBUG # total size: 8
Dec 11 23:08:23-723864 cadet-api-32318 DEBUG # nothing left to transmit
Dec 11 23:08:23-723868 cadet-api-32318 DEBUG # Send packet() END
Dec 11 23:08:23-725438 cadet-api-32318 DEBUG
Dec 11 23:08:23-725456 cadet-api-32318 DEBUG Received a message: {
  LOCAL_DATA}
Dec 11 23:08:23-725464 cadet-api-32318 DEBUG Got a data message!
Dec 11 23:08:23-725473 cadet-api-32318 DEBUG FWD data on channel 6DEV
[B0000000]
Dec 11 23:08:23-725479 cadet-api-32318 DEBUG 64000 bytes
Dec 11 23:08:23-725486 cadet-api-32318 DEBUG payload type 645 (UNKNOWN
TYPE)
Dec 11 23:08:23-725493 cadet-api-32318 DEBUG checking handler for
type 644
Dec 11 23:08:23-725499 cadet-api-32318 DEBUG checking handler for
type 645
Dec 11 23:08:23-725505 scalarproduct-bob-32318 DEBUG Received 124 crypto
values from Alice
Dec 11 23:08:23-725518 cadet-api-32318 DEBUG Sending ACK on channel B0000000
Dec 11 23:08:23-725528 cadet-api-32318 DEBUG Sending message to
service: { LOCAL_ACK}
Dec 11 23:08:23-725535 cadet-api-32318 DEBUG queued
Dec 11 23:08:23-725540 cadet-api-32318 DEBUG calling ntfy tmt rdy for
8 bytes
Dec 11 23:08:23-725548 cadet-api-32318 DEBUG callback completed successfully
Dec 11 23:08:23-725555 cadet-api-32318 DEBUG message processed
Dec 11 23:08:23-725566 cadet-api-32318 DEBUG
Dec 11 23:08:23-725573 cadet-api-32318 DEBUG # Send packet() Buffer 8
Dec 11 23:08:23-725579 cadet-api-32318 DEBUG # message internal
Dec 11 23:08:23-725585 cadet-api-32318 DEBUG # cadet internal traffic,
type { LOCAL_ACK}
Dec 11 23:08:23-725592 cadet-api-32318 DEBUG # total size: 8
Dec 11 23:08:23-725598 cadet-api-32318 DEBUG # nothing left to transmit
Dec 11 23:08:23-725603 cadet-api-32318 DEBUG # Send packet() END
Dec 11 23:08:23-726169 cadet-api-32318 DEBUG
Dec 11 23:08:23-726184 cadet-api-32318 DEBUG Received a message: {
  LOCAL_DATA}
Dec 11 23:08:23-726192 cadet-api-32318 DEBUG Got a data message!
Dec 11 23:08:23-726203 cadet-api-32318 DEBUG FWD data on channel 6DEV
[B0000000]
Dec 11 23:08:23-726208 cadet-api-32318 DEBUG 16012 bytes
Dec 11 23:08:23-726212 cadet-api-32318 DEBUG payload type 645 (UNKNOWN
TYPE)
Dec 11 23:08:23-726215 cadet-api-32318 DEBUG checking handler for
type 644
Dec 11 23:08:23-726219 cadet-api-32318 DEBUG checking handler for
type 645
Dec 11 23:08:23-726223 scalarproduct-bob-32318 DEBUG Received 31 crypto
values from Alice
Dec 11 23:08:23-726230 scalarproduct-bob-32318 DEBUG Received
everything, building reply for Alice
Dec 11 23:08:31-898531 cadet-api-32242 DEBUG CADET NOTIFY TRANSMIT READY
Dec 11 23:08:31-898562 cadet-api-32242 DEBUG on channel B0000000
Dec 11 23:08:31-898571 cadet-api-32242 DEBUG allow_send 1
Dec 11 23:08:31-898579 cadet-api-32242 DEBUG to origin
Dec 11 23:08:31-898587 cadet-api-32242 DEBUG payload size 63992
Dec 11 23:08:31-898596 cadet-api-32242 DEBUG total size 64000
Dec 11 23:08:31-898604 cadet-api-32242 DEBUG call client notify tmt rdy
Dec 11 23:08:31-898615 cadet-api-32242 DEBUG CADET NOTIFY TRANSMIT READY END
Dec 11 23:08:31-898779 cadet-api-32242 DEBUG Sending ACK on channel B0000000
Dec 11 23:08:31-898795 cadet-api-32242 DEBUG Sending message to
service: { LOCAL_ACK}
Dec 11 23:08:31-898803 cadet-api-32242 DEBUG queued
Dec 11 23:08:31-898811 cadet-api-32242 DEBUG callback completed successfully
Dec 11 23:08:31-898818 cadet-api-32242 DEBUG message processed
Dec 11 23:08:31-898840 cadet-api-32242 DEBUG # message internal
Dec 11 23:08:31-899009 cadet-api-32242 DEBUG Destroying channel
Dec 11 23:08:31-899027 cadet-api-32242 DEBUG destroy_channel B0000000
Dec 11 23:08:31-899036 cadet-api-32242 DEBUG calling cleaner
Dec 11 23:08:31-899050 cadet-api-32242 DEBUG Sending message to
service: { CHANNEL_DESTROY}
Dec 11 23:08:31-899059 cadet-api-32242 DEBUG queued
Dec 11 23:08:31-899066 cadet-api-32242 DEBUG calling ntfy tmt rdy for
48 bytes
Dec 11 23:08:31-899360 cadet-api-32242 DEBUG Cadet service disconnected,
reconnecting
Dec 11 23:08:31-899376 cadet-api-32242 DEBUG Requested RECONNECT,
destroying all channels
Dec 11 23:08:31-899395 cadet-api-32242 DEBUG CADET DISCONNECT



Dec 11 23:09:15-853597 scalarproduct-bob-32318 DEBUG Sending 61/403
crypto values to Alice
Dec 11 23:09:15-853648 cadet-api-32318 DEBUG CADET NOTIFY TRANSMIT READY
Dec 11 23:09:15-853662 cadet-api-32318 DEBUG on channel B0000000
Dec 11 23:09:15-853671 cadet-api-32318 DEBUG allow_send 1
Dec 11 23:09:15-853679 cadet-api-32318 DEBUG to origin
Dec 11 23:09:15-853688 cadet-api-32318 DEBUG payload size 63992
Dec 11 23:09:15-853697 cadet-api-32318 DEBUG total size 64000
Dec 11 23:09:15-853707 cadet-api-32318 DEBUG call client notify tmt rdy
Dec 11 23:09:15-853718 cadet-api-32318 DEBUG CADET NOTIFY TRANSMIT READY END
Dec 11 23:09:15-853727 scalarproduct-bob-32318 DEBUG Sending 62
additional crypto values to Alice
Dec 11 23:09:15-853768 scalarproduct-bob-32318 DEBUG Sending 62
additional crypto values to Alice
Dec 11 23:09:15-853814 scalarproduct-bob-32318 DEBUG Sending 62
additional crypto values to Alice
Dec 11 23:09:15-853853 scalarproduct-bob-32318 DEBUG Sending 62
additional crypto values to Alice
Dec 11 23:09:15-853899 scalarproduct-bob-32318 DEBUG Sending 62
additional crypto values to Alice
Dec 11 23:09:15-853940 scalarproduct-bob-32318 DEBUG Sending 32
additional crypto values to Alice
Dec 11 23:09:15-853968 scalarproduct-bob-32318 DEBUG All values queued
for Alice, Bob is done
Dec 11 23:09:15-853978 cadet-api-32318 DEBUG Sending ACK on channel B0000000
Dec 11 23:09:15-853988 cadet-api-32318 DEBUG Sending message to
service: { LOCAL_ACK}
Dec 11 23:09:15-853997 cadet-api-32318 DEBUG queued
Dec 11 23:09:15-854005 cadet-api-32318 DEBUG callback completed successfully
Dec 11 23:09:15-854012 cadet-api-32318 DEBUG message processed
Dec 11 23:09:15-854034 cadet-api-32318 DEBUG
Dec 11 23:09:15-854044 cadet-api-32318 DEBUG # Send packet() Buffer 64000
Dec 11 23:09:15-854054 cadet-api-32318 DEBUG # message payload ok
Dec 11 23:09:15-854062 cadet-api-32318 DEBUG # payload
Dec 11 23:09:15-854095 cadet-api-32318 DEBUG # payload type 647
(UNKNOWN TYPE)
Dec 11 23:09:15-854106 cadet-api-32318 DEBUG # message internal
Dec 11 23:09:15-854113 cadet-api-32318 DEBUG # total size: 64000
Dec 11 23:09:15-854121 cadet-api-32318 DEBUG # message internal
Dec 11 23:09:15-854128 cadet-api-32318 DEBUG # next size: 8
Dec 11 23:09:15-854137 cadet-api-32318 DEBUG # Send packet() END
Dec 11 23:09:15-854167 cadet-api-32318 DEBUG CADET NOTIFY TRANSMIT READY
Dec 11 23:09:15-854186 cadet-api-32318 DEBUG on channel B0000000
Dec 11 23:09:15-854198 cadet-api-32318 DEBUG allow_send 0
Dec 11 23:09:15-854210 cadet-api-32318 DEBUG to origin
Dec 11 23:09:15-854222 cadet-api-32318 DEBUG payload size 63992
Dec 11 23:09:15-854234 cadet-api-32318 DEBUG total size 64000
Dec 11 23:09:15-854269 cadet-api-32318 DEBUG
Dec 11 23:09:15-854281 cadet-api-32318 DEBUG # Send packet() Buffer 64000
Dec 11 23:09:15-854288 cadet-api-32318 DEBUG # message internal
Dec 11 23:09:15-854296 cadet-api-32318 DEBUG # cadet internal traffic,
type { LOCAL_ACK}
Dec 11 23:09:15-854304 cadet-api-32318 DEBUG # total size: 8
Dec 11 23:09:15-854313 cadet-api-32318 DEBUG # can't transmit any more
Dec 11 23:09:15-854320 cadet-api-32318 DEBUG # Send packet() END
TagsNo tags attached.

Relationships

related to 0003482 closedBart Polot Use a ratcheting scheme in CADET for really _PERFECT_ forward secrecy. 

Activities

Bart Polot

2015-01-15 20:12

manager   ~0008790

Seems to be working for me...

real 0m11.232s
user 0m0.007s
sys 0m0.010s
         core # bytes encrypted: 19901
         core # bytes encrypted: 65817
Terminating testbed...



real 0m11.304s
user 0m0.010s
sys 0m0.000s
         core # bytes encrypted: 20115
         core # bytes encrypted: 65285
Terminating testbed...


real 0m11.175s
user 0m0.003s
sys 0m0.007s
         core # bytes encrypted: 19901
         core # bytes encrypted: 65613
Terminating testbed...

cy1

2015-01-15 21:54

reporter   ~0008794

It might be good to pair the "Got an ACK!" message with a matching "Sent an ACK!" message, if only for debugging this. "# Send packet() END" just doesn't really convey that an ACK was what was sent clearly.

How did bob get an ACK on channel B0000000? It only says bob created that channel previously, and none of the other processes mentioned sending anything to it. Also only process 32317 mentions channel 80000000, yet Bob still receives two ACKs to that channel, somehow.

If Bob is sending two messages at once, you probably should rewrite TCP sliding windows, so that he doesn't require an acknowledgement for one before sending the next. I don't know if that would fix the problem persay, but it would keep Bob from being stuck waiting for the ack. He sure doesn't seem stuck in the debug log

It says "scalarproduct-alice-32317 DEBUG Sending 124/403 crypto values to Bob" but you only mention Bob sending messages to Alice in your report. What is Alice sending Bob, besides ACKs? I'm guessing that "Dec 11 23:08:23-719547 cadet-api-32317 DEBUG message processed" is where Bob gets hung up, but it doesn't really explain the previous two ACKs that Bob received on the very same channel, and why he didn't get hung up on those.

Just my thoughts. I don't really understand this stuff, but I'll always be willing to give it a shot.

Christian Grothoff

2015-01-16 11:32

manager   ~0008796

When I set the benchmark size higher,
grothoff@pixel:~/svn/gnunet/src/scalarproduct$ svn diff
Index: perf_scalarproduct.sh
===================================================================
--- perf_scalarproduct.sh (revision 34898)
+++ perf_scalarproduct.sh (working copy)
@@ -10,7 +10,7 @@
 # 400 149 23
 # 800 304 32
 # Configure benchmark size:
-SIZE=25
+SIZE=1600
 #
 # Construct input vectors:
 INPUTALICE="-k CCC -e '"


I now get:

Jan 16 11:28:37-536924 cadet-tun-30153 WARNING Wrong PONG challenge on 6YNB
Jan 16 11:28:37-545282 cadet-tun-30153 WARNING Wrong PONG challenge on 6YNB
Jan 16 11:28:37-553264 cadet-tun-30153 WARNING Wrong PONG challenge on 6YNB
Jan 16 11:28:37-561299 cadet-tun-30153 WARNING Wrong PONG challenge on 6YNB

(printed lots)

Test passes, but those warnings and CADET having 100% CPU usage while doing 'nothing' is still not good.

Bart Polot

2015-01-16 19:41

manager   ~0008800

> It might be good to pair the "Got an ACK!" message with a matching "Sent an
> ACK!" message, if only for debugging this. "# Send packet() END" just doesn't
> really convey that an ACK was what was sent clearly.
The ACK the api talks about is a local ACK sent by the service talling the client that more data can be sent. Since this trace doesn't log the service, this part is not seen.


> How did bob get an ACK on channel B0000000? It only says bob created that
> channel previously, and none of the other processes mentioned sending anything
> to it. Also only process 32317 mentions channel 80000000, yet Bob still
> receives two ACKs to that channel, somehow.
It's the service telling Bob that Alice has completed the handshake and Bob can send data. This causes the API to activate the callback given to transmit_ready, if any.

>If Bob is sending two messages at once, you probably should rewrite TCP sliding
>windows, so that he doesn't require an acknowledgement for one before sending
>the next. I don't know if that would fix the problem persay, but it would keep
>Bob from being stuck waiting for the ack. He sure doesn't seem stuck in the
>debug log

The API client<->service only allows one message at a time, calling transmit_ready a second time will trigger an assertion.

> It says "scalarproduct-alice-32317 DEBUG Sending 124/403 crypto values to
> Bob" but you only mention Bob sending messages to Alice in your report. What
> is Alice sending Bob, besides ACKs? I'm guessing that "Dec 11 23:08:23-719547
> cadet-api-32317 DEBUG message processed" is where Bob gets hung up, but it
> doesn't really explain the previous two ACKs that Bob received on the very
> same channel, and why he didn't get hung up on those.
If Bob doesn't send anything, it will not show. The service does the ACK'ing for Bob. I don't know exactly what the testcase does, but this is not unexpected behavior.

Bart Polot

2015-01-16 19:47

manager   ~0008801

The PONG warning messages are caused by the old handshake being timing sensitive. It will go away with the full Axolotl implementation (0003482). This bug (failing to send traffic) seems to be solved now...

Issue History

Date Modified Username Field Change
2014-12-11 23:19 Christian Grothoff New Issue
2014-12-11 23:19 Christian Grothoff Status new => assigned
2014-12-11 23:19 Christian Grothoff Assigned To => Bart Polot
2015-01-15 20:12 Bart Polot Note Added: 0008790
2015-01-15 20:12 Bart Polot Status assigned => feedback
2015-01-15 21:54 cy1 Note Added: 0008794
2015-01-16 11:32 Christian Grothoff Note Added: 0008796
2015-01-16 11:32 Christian Grothoff Status feedback => assigned
2015-01-16 19:41 Bart Polot Note Added: 0008800
2015-01-16 19:45 Bart Polot Relationship added related to 0003482
2015-01-16 19:47 Bart Polot Note Added: 0008801
2015-01-16 19:47 Bart Polot Status assigned => resolved
2015-01-16 19:47 Bart Polot Fixed in Version => 0.11.0pre66
2015-01-16 19:47 Bart Polot Resolution open => fixed
2018-06-07 00:25 Christian Grothoff Status resolved => closed