00000000 0.00000000 [2028] xp_send_file: file = client/testfile.dat 00000001 0.00006844 [2028] to_xp_server: message = announce-ft [client-source %client/testfile.dat size 714 key "s1vc."] 00000002 0.00012069 [2028] getting mime header size channel->automatic_mime == 1 00000003 0.00018885 [2028] finished checking for MIME configuration=1 for channel=13 00000004 0.00025702 [2028] mime headers size calculated for channel 13 was: 2 00000005 0.00034585 [2028] new message to sent, type=1 channel=13 msgno=1 size (71) = msg size (69) + mime size (2) 00000006 0.00040340 [2028] updating channel sending status to: msgno=1, rpyno=0, seqno=87, ansno=0.. 00000007 0.00048246 [2028] SignalObjectAndWait finished, because: WAIT_OBJECT_0 00000008 0.00057437 [2028] finished vortex_cond_wait from vortex_thread.c:919 00000009 0.00062298 [2028] to_xp_server: getting blocked until reply from xpeers II server arrives. 00000010 0.00069003 [2028] a new message to be sequenced: (channel=13, size=71, sequencer-queue=0).. 00000011 0.00081491 [2028] getting reply at wait reply from the queue 00000012 0.00087525 [2028] called vortex_cond_timedwait from vortex_thread.c:986 00000013 0.00090011 [2028] increased connection id=1 reference to 3 by (vortex sequencer) 00000014 0.00096493 [2028] sequence operation (0p122ead8): type=1, msgno=1, next seq no=16 message size=71 max seq no=4095 step=0 00000015 0.00102555 [2028] the channel is not stalled, continue with sequencing, about to send 71 bytes as payload... 00000016 0.00108561 [2028] sequencing next message: type=1, channel num=13, msgno=1, more=0, next seq=16 size=71 ansno=0 00000017 0.00118423 [2028] frame built, send the frame directly 00000018 0.00135548 [2028] Sending message, size (94) over connection id=1, errno=0 00000019 0.00147002 [844] something to read 00000020 0.00153176 [2028] bytes written: 94 00000021 0.00158679 [844] from='get-next' allocating a new frame id=14 00000022 0.00164658 [2028] write on socket request=94 written=94 00000023 0.00172704 [2028] channel=13 unref called, ref count status after calling=2 00000024 0.00175274 [2028] it seems the message was sent completely 00000025 0.00182928 [844] Frame received on channel 13, content type=, transfer encoding=, payload size=71, mime content size=0 00000026 0.00187817 [844] passed initial accept stage 00000027 0.00194690 [2028] channel=13 unref called, ref count status after calling=1 00000028 0.00199355 [844] passed connection existence stage 00000029 0.00210390 [2028] decreased connection id=1 reference count to 2 decreased by (vortex sequencer) 00000030 0.00212932 [2028] called vortex_cond_wait from vortex_thread.c:919 00000031 0.00221313 [844] SEQ FRAME: not updated, already not consumed half of window advertised: 88 < (4096 / 2) 00000032 0.00225504 [844] frame-content-size=71, frame-payload-size=71, 00000033 0.00230392 [844] window_size=4096, consumed_seqno=87, new_max_seq_no_accepted=4182 00000034 0.00236259 [844] max_seq_no_accepted=4095 00000035 0.00245450 [844] about to checking expected message to be received on this channel 00000036 0.00251512 [844] passed message number checking stage 00000037 0.00257351 [844] updating channel receiving status to: msgno=1, rpyno=0, seqno=87, ansno=0.. 00000038 0.00263246 [844] passed channel update status due to frame received stage 00000039 0.00269084 [844] passed frame checking stage 00000040 0.00274951 [844] found MIME message without headers 00000041 0.00280790 [844] no waiting queue for this message: 1 00000042 0.00287187 [844] it seems you didn't define a second level received handler 00000043 0.00293920 [844] increased connection id=2 reference to 2 by first level handler (frame received) 00000044 0.00299116 [844] frame delivered on first (profile) level handler channel 00000045 0.00303865 [844] SignalObjectAndWait finished, because: WAIT_OBJECT_0 00000046 0.00309872 [844] finished vortex_cond_wait from vortex_thread.c:919 00000047 0.00318700 [844] --> thread from pool processing new job 00000048 0.00322080 [844] xp_ans: connection = 2, channel = 13, profile = http://xpeers.net/xp_msg 00000049 0.00327667 [844] xp_ans: payload = announce-ft [client-source %client/testfile.dat size 714 key "s1vc."] 00000050 0.00384993 [844] to_rebol_processor: socket created 00000051 0.00400945 [844] to_rebol_processor: data send, message = xp-ans [id 2 msg announce-ft [client-source %client/testfile.dat size 714 key "s1vc."]] 00000052 0.00538532 [844] xp_request_file: target_path = server/testfile.dat, source_file_key = s1vc. 00000053 0.00558311 [844] xp_request_file: checking profile 0, slice = 1024 00000054 0.00563424 [844] xp_request_file: found FT channel pointer = 011BDFA0 00000055 0.00566860 [844] to_rebol_processor: socket closed 00000056 0.00574263 [844] checking channel to be ready (-1 == -1) && reply_processed=1 00000057 0.00592841 [844] xp_request_file: channel = 4, using profile 0, slice = 1024 00000058 0.00599350 [844] getting mime header size channel->automatic_mime == 1 00000059 0.00607312 [844] finished checking for MIME configuration=1 for channel=13 00000060 0.00613234 [844] getting mime header size channel->automatic_mime == 0 00000061 0.00619213 [844] mime headers size calculated for channel 13 was: 2 00000062 0.00625443 [844] new reply message to sent size (12) = msg size (10) + mime size (2) 00000063 0.00628292 [844] sending reply for message 1 (size: 10, sequencer queue status: 0, channel queue status: 0) 00000064 0.00637427 [844] getting mime header size channel->automatic_mime == 1 00000065 0.00643573 [844] finished checking for MIME configuration=1 for channel=4 00000066 0.00650027 [844] updating channel sending status to: msgno=-1, rpyno=2, seqno=24, ansno=0.. 00000067 0.00653407 [844] xp_ans: RPY send 00000068 0.00659805 [844] mime headers size calculated for channel 4 was: 2 00000069 0.00664358 [844] SignalObjectAndWait finished, because: WAIT_OBJECT_0 00000070 0.00670309 [844] new message to sent, type=1 channel=4 msgno=0 size (7) = msg size (5) + mime size (2) 00000071 0.00680980 [844] updating channel sending status to: msgno=0, rpyno=0, seqno=7, ansno=0.. 00000072 0.00687071 [844] finished vortex_cond_wait from vortex_thread.c:919 00000073 0.00690758 [844] invocation frame received handler for channel 13 finished (first level: profiles) 00000074 0.00697323 [844] xp_request_file: sync queue pointer = 011BDBD8 00000075 0.00705062 [844] a new message to be sequenced: (channel=13, size=12, sequencer-queue=1).. 00000076 0.00709420 [844] called vortex_cond_wait from vortex_thread.c:919 00000077 0.00719337 [844] increased connection id=2 reference to 3 by (vortex sequencer) 00000078 0.00725316 [844] sequence operation (0pbeffd0): type=2, msgno=1, next seq no=12 message size=12 max seq no=4095 step=0 00000079 0.00729646 [844] channel=13 unref called, ref count status after calling=2 00000080 0.00733948 [844] the channel is not stalled, continue with sequencing, about to send 12 bytes as payload... 00000081 0.00739982 [844] decreased connection id=2 reference count to 2 decreased by first level handler (frame received) 00000082 0.00747832 [844] sequencing next message: type=2, channel num=13, msgno=1, more=0, next seq=12 size=12 ansno=0 00000083 0.00755794 [844] frame built, send the frame directly 00000084 0.00761661 [844] deallocating frame id=14 00000085 0.00764203 [844] Sending message, size (35) over connection id=2, errno=0 00000086 0.00782725 [2028] something to read 00000087 0.00786776 [2028] from='get-next' allocating a new frame id=16 00000088 0.00793509 [844] --> thread from pool waiting for jobs 00000089 0.00806359 [844] bytes written: 35 00000090 0.00809712 [844] called vortex_cond_wait from vortex_thread.c:919 00000091 0.00818819 [2028] Frame received on channel 13, content type=, transfer encoding=, payload size=12, mime content size=0 00000092 0.00824770 [844] write on socket request=35 written=35 00000093 0.00832704 [844] updating channel sending status to: msgno=-1, rpyno=2, seqno=24, ansno=0.. 00000094 0.00843124 [2028] passed initial accept stage 00000095 0.00858126 [2028] passed connection existence stage 00000096 0.00868378 [844] channel=13 unref called, ref count status after calling=2 00000097 0.00876620 [2028] SEQ FRAME: not updated, already not consumed half of window advertised: 25 < (4096 / 2) 00000098 0.00883660 [844] it seems the message was sent completely 00000099 0.00888688 [2028] frame-content-size=12, frame-payload-size=12, 00000100 0.00898997 [844] channel=13 unref called, ref count status after calling=1 00000101 0.00911065 [844] decreased connection id=2 reference count to 1 decreased by (vortex sequencer) 00000102 0.00919279 [2028] window_size=4096, consumed_seqno=24, new_max_seq_no_accepted=4119 00000103 0.00922631 [844] a new message to be sequenced: (channel=4, size=7, sequencer-queue=0).. 00000104 0.00929420 [2028] max_seq_no_accepted=4095 00000105 0.00937130 [2028] passed message number checking stage 00000106 0.00947383 [2028] setting pending reply processed=0 for channel=13 00000107 0.00960988 [844] increased connection id=2 reference to 2 by (vortex sequencer) 00000108 0.00969313 [844] sequence operation (0pefc350): type=1, msgno=0, next seq no=0 message size=7 max seq no=4095 step=0 00000109 0.00977499 [2028] updating channel receiving status to: msgno=-1, rpyno=2, seqno=24, ansno=0.. 00000110 0.00984343 [844] the channel is not stalled, continue with sequencing, about to send 7 bytes as payload... 00000111 0.00988841 [2028] passed channel update status due to frame received stage 00000112 0.01000099 [844] sequencing next message: type=1, channel num=4, msgno=0, more=0, next seq=0 size=7 ansno=0 00000113 0.01010045 [844] frame built, send the frame directly 00000114 0.01023482 [844] Sending message, size (27) over connection id=2, errno=0 00000115 0.01031723 [2028] passed frame checking stage 00000116 0.01035020 [844] bytes written: 27 00000117 0.01043177 [2028] found MIME message without headers 00000118 0.01054715 [844] write on socket request=27 written=27 00000119 0.01066001 [844] channel=4 unref called, ref count status after calling=2 00000120 0.01068851 [2028] found a frame that were waited by a thread: reply no='1' over channel=13 00000121 0.01076506 [844] it seems the message was sent completely 00000122 0.01082177 [2028] SignalObjectAndWait finished, because: WAIT_OBJECT_0 00000123 0.01089161 [2028] finished vortex_cond_timedwait (result: 1) from vortex_thread.c:986 00000124 0.01095949 [2028] received reply, freeing wait reply object 00000125 0.01109834 [2028] to_xp_server: answer arrived, resuming execution. answer = xp_ans: OK 00000126 0.01117153 [844] channel=4 unref called, ref count status after calling=1 00000127 0.01126512 [2028] frame delivered on second (channel) level handler channel 00000128 0.01129417 [844] decreased connection id=2 reference count to 1 decreased by (vortex sequencer) 00000129 0.01215853 [2028] deallocating frame id=16 00000130 0.01555477 [2028] something to read 00000131 0.01566875 [844] called vortex_cond_wait from vortex_thread.c:919 00000132 0.01581709 [2028] from='get-next' allocating a new frame id=17 00000133 0.01587995 [844] SignalObjectAndWait finished, because: WAIT_OBJECT_0 00000134 0.01593247 [2028] Frame received on channel 4, content type=, transfer encoding=, payload size=7, mime content size=0 00000135 0.01597102 [844] finished vortex_cond_wait from vortex_thread.c:919 00000136 0.01604785 [2028] passed initial accept stage 00000137 0.01609534 [2028] passed connection existence stage 00000138 0.01618446 [844] called vortex_cond_wait from vortex_thread.c:919 00000139 0.01624257 [2028] SEQ FRAME: not updated, already not consumed half of window advertised: 8 < (4096 / 2) 00000140 0.01630179 [2028] frame-content-size=7, frame-payload-size=7, 00000141 0.01635962 [2028] window_size=4096, consumed_seqno=7, new_max_seq_no_accepted=4102 00000142 0.01641773 [2028] max_seq_no_accepted=4095 00000143 0.01647528 [2028] about to checking expected message to be received on this channel 00000144 0.01653422 [2028] passed message number checking stage 00000145 0.01659205 [2028] updating channel receiving status to: msgno=0, rpyno=0, seqno=7, ansno=0.. 00000146 0.01664960 [2028] passed channel update status due to frame received stage 00000147 0.01670715 [2028] passed frame checking stage 00000148 0.01676470 [2028] found MIME message without headers 00000149 0.01682253 [2028] no waiting queue for this message: 0 00000150 0.01688595 [2028] it seems you didn't define a second level received handler 00000151 0.01691053 [2028] increased connection id=1 reference to 3 by first level handler (frame received) 00000152 0.01700021 [2028] SignalObjectAndWait finished, because: WAIT_OBJECT_0 00000153 0.01704490 [2028] finished vortex_cond_wait from vortex_thread.c:919 00000154 0.01710385 [2028] --> thread from pool processing new job 00000155 0.01717229 [2028] frame delivered on first (profile) level handler channel 00000156 0.01753994 [2028] ft_ans_byte: called, message = s1vc., msg-number = 0 00000157 0.01756648 [2028] ft_ans_byte: Sending bytes 714 00000158 0.01762570 [2028] getting mime header size channel->automatic_mime == 0 00000159 0.01768661 [2028] getting mime header size channel->automatic_mime == 1 00000160 0.01774499 [2028] finished checking for MIME configuration=1 for channel=4 00000161 0.01780338 [2028] mime headers size calculated for channel 4 was: 2 00000162 0.01787965 [2028] new reply message to sent size (716) = msg size (714) + mime size (2) 00000163 0.01792546 [2028] sending reply for message 0 (size: 714, sequencer queue status: 0, channel queue status: 0) 00000164 0.01798469 [2028] updating channel sending status to: msgno=-1, rpyno=0, seqno=716, ansno=1.. 00000165 0.01806515 [2028] SignalObjectAndWait finished, because: WAIT_OBJECT_0 00000166 0.01810984 [2028] finished vortex_cond_wait from vortex_thread.c:919 00000167 0.01818248 [2028] a new message to be sequenced: (channel=4, size=716, sequencer-queue=0).. 00000168 0.01824953 [2028] ft_ans_byte: Sending bytes 0 00000169 0.01829171 [2028] getting mime header size channel->automatic_mime == 1 00000170 0.01838390 [2028] increased connection id=1 reference to 4 by (vortex sequencer) 00000171 0.01842972 [2028] sequence operation (0p1231400): type=3, msgno=0, next seq no=0 message size=716 max seq no=4095 step=0 00000172 0.01850431 [2028] finished checking for MIME configuration=1 for channel=4 00000173 0.01858085 [2028] mime headers size calculated for channel 4 was: 2 00000174 0.01867472 [2028] the channel is not stalled, continue with sequencing, about to send 716 bytes as payload... 00000175 0.01873702 [2028] sequencing next message: type=3, channel num=4, msgno=0, more=0, next seq=0 size=716 ansno=0 00000176 0.01879569 [2028] new reply message to sent size (2) = msg size (0) + mime size (2) 00000177 0.01885603 [2028] frame built, send the frame directly 00000178 0.01898174 [2028] Sending message, size (740) over connection id=1, errno=0 00000179 0.01903957 [844] something to read 00000180 0.01915998 [2028] bytes written: 740 00000181 0.01932843 [844] from='get-next' allocating a new frame id=15 00000182 0.01938822 [2028] sending reply for message 0 (size: 0, sequencer queue status: 0, channel queue status: 0) 00000183 0.01945108 [2028] write on socket request=740 written=740 00000184 0.01948935 [2028] updating channel sending status to: msgno=-1, rpyno=1, seqno=718, ansno=1.. 00000185 0.01957455 [844] Frame received on channel 4, content type=, transfer encoding=, payload size=716, mime content size=0 00000186 0.01964160 [844] passed initial accept stage 00000187 0.01967513 [2028] channel=4 unref called, ref count status after calling=3 00000188 0.01975139 [844] passed connection existence stage 00000189 0.01981034 [844] SEQ FRAME: not updated, already not consumed half of window advertised: 717 < (4096 / 2) 00000190 0.01991566 [2028] ft_ans_byte: end task (pid: 2028), bytes transferred: 714 (ans/nul pattern) 00000191 0.01996734 [2028] it seems the message was sent completely 00000192 0.02005339 [844] frame-content-size=716, frame-payload-size=716, 00000193 0.02008775 [844] window_size=4096, consumed_seqno=716, new_max_seq_no_accepted=4811 00000194 0.02015647 [2028] channel=4 unref called, ref count status after calling=3 00000195 0.02026598 [2028] invocation frame received handler for channel 4 finished (first level: profiles) 00000196 0.02031012 [2028] decreased connection id=1 reference count to 3 decreased by (vortex sequencer) 00000197 0.02037941 [844] max_seq_no_accepted=4095 00000198 0.02049031 [844] passed message number checking stage 00000199 0.02055652 [2028] channel=4 unref called, ref count status after calling=2 00000200 0.02060988 [844] setting pending reply processed=0 for channel=4 00000201 0.02066911 [2028] a new message to be sequenced: (channel=4, size=2, sequencer-queue=0).. 00000202 0.02070654 [2028] decreased connection id=1 reference count to 2 decreased by first level handler (frame received) 00000203 0.02079007 [844] updating channel receiving status to: msgno=-1, rpyno=0, seqno=716, ansno=0.. 00000204 0.02086271 [844] passed channel update status due to frame received stage 00000205 0.02092389 [844] passed frame checking stage 00000206 0.02098479 [2028] deallocating frame id=17 00000207 0.02103731 [844] found MIME message without headers 00000208 0.02107698 [2028] --> thread from pool waiting for jobs 00000209 0.02116191 [844] no waiting queue for this message: 0 00000210 0.02124320 [844] increased connection id=2 reference to 2 by second level invocation (frame received) 00000211 0.02131025 [2028] increased connection id=1 reference to 3 by (vortex sequencer) 00000212 0.02137395 [844] about to invoke the frame received under a newly created handler 00000213 0.02143429 [2028] called vortex_cond_wait from vortex_thread.c:919 00000214 0.02149323 [2028] sequence operation (0p1231a68): type=5, msgno=0, next seq no=716 message size=2 max seq no=4095 step=0 00000215 0.02159101 [2028] the channel is not stalled, continue with sequencing, about to send 2 bytes as payload... 00000216 0.02168935 [2028] sequencing next message: type=5, channel num=4, msgno=0, more=0, next seq=716 size=2 ansno=1 00000217 0.02176254 [2028] frame built, send the frame directly 00000218 0.02185334 [844] frame delivered on second (channel) level handler channel 00000219 0.02193268 [844] SignalObjectAndWait finished, because: WAIT_OBJECT_0 00000220 0.02201118 [844] finished vortex_cond_wait from vortex_thread.c:919 00000221 0.02205979 [844] --> thread from pool processing new job 00000222 0.02225450 [2028] Sending message, size (24) over connection id=1, errno=0 00000223 0.02232602 [2028] bytes written: 24 00000224 0.02245677 [844] something to read 00000225 0.02253443 [844] STARTED the frame received handler invocation (new task): ANS 4 0 . 0 716 00000226 0.02259673 [844] ft_stream_receive: channel = 4, msg-number = 0 00000227 0.02269842 [2028] write on socket request=24 written=24 00000228 0.02299147 [844] from='get-next' allocating a new frame id=16 00000229 0.02302639 [2028] channel=4 unref called, ref count status after calling=2 00000230 0.02309483 [844] Frame received on channel 4, content type=, transfer encoding=, payload size=2, mime content size=0 00000231 0.02319792 [844] frame received invocation for second level FINISHED (new task): ANS 4 0 . 0 716 00000232 0.02326637 [2028] it seems the message was sent completely 00000233 0.02336442 [2028] channel=4 unref called, ref count status after calling=1 00000234 0.02350327 [844] deallocating frame id=15 00000235 0.02359462 [844] passed initial accept stage 00000236 0.02366334 [2028] decreased connection id=1 reference count to 2 decreased by (vortex sequencer) 00000237 0.02370860 [844] invocation frame received handler for channel 4 finished (second level: channel), ref count: channel=2 connection=2 00000238 0.02379716 [2028] called vortex_cond_wait from vortex_thread.c:919 00000239 0.02385862 [844] passed connection existence stage 00000240 0.02398601 [844] channel=4 unref called, ref count status after calling=1 00000241 0.02407680 [844] decreased connection id=2 reference count to 1 decreased by second level handler (frame received) 00000242 0.02415111 [844] SEQ FRAME: updating due to NUL frame found 00000243 0.02417961 [844] --> thread from pool waiting for jobs 00000244 0.02425001 [844] SEQ FRAME: updating allowed max seq no to be received from 4095 to 4813 (delta: 718, ackno: 718, window_size: 4096) 00000245 0.02433577 [844] called vortex_cond_wait from vortex_thread.c:919 00000246 0.02441958 [844] notifying remote side that current buffer status is SEQ 4 718 4096 00000247 0.02447434 [844] Sending message, size (16) over connection id=2, errno=0 00000248 0.02467045 [2028] something to read 00000249 0.02471599 [2028] from='get-next' allocating a new frame id=18 00000250 0.02479254 [844] bytes written: 16 00000251 0.02486769 [2028] passed initial accept stage 00000252 0.02496267 [844] write on socket request=16 written=16 00000253 0.02502860 [2028] passed connection existence stage 00000254 0.02507051 [2028] received a SEQ frame: SEQ 4 718 4096 00000255 0.02516605 [844] channel=0 unref called, ref count status after calling=1 00000256 0.02521410 [844] passed message number checking stage 00000257 0.02526634 [2028] Received SEQ frame update operation: channel=4 ackno=718 window=4096 00000258 0.02539205 [2028] received SEQ frame, updated maximum seq no allowed from 4095 to 4813 00000259 0.02546385 [844] found MIME message without headers 00000260 0.02553481 [2028] deallocating frame id=18 00000261 0.02556275 [844] setting pending reply processed=0 for channel=4 00000262 0.02562002 [2028] about to check for pending queue message not sequenced.. 00000263 0.02568734 [2028] returning the first pending message: current length=0 for channel=4 00000264 0.02582842 [2028] there is no messages pending to be sequenced, over the channel=4 00000265 0.02589603 [844] updating channel receiving status to: msgno=-1, rpyno=1, seqno=718, ansno=0.. 00000266 0.02592508 [844] passed channel update status due to frame received stage 00000267 0.02599129 [844] passed frame checking stage 00000268 0.02605806 [844] no waiting queue for this message: 0 00000269 0.02612790 [844] increased connection id=2 reference to 2 by second level invocation (frame received) 00000270 0.02624412 [844] about to invoke the frame received under a newly created handler 00000271 0.02627317 [844] SignalObjectAndWait finished, because: WAIT_OBJECT_0 00000272 0.02633994 [844] frame delivered on second (channel) level handler channel 00000273 0.02641732 [844] finished vortex_cond_wait from vortex_thread.c:919 00000274 0.02648521 [844] --> thread from pool processing new job 00000275 0.02655338 [844] STARTED the frame received handler invocation (new task): NUL 4 0 . 716 2 00000276 0.02667238 [844] ft_stream_receive: channel = 4, msg-number = 0 00000277 0.02673077 [844] SignalObjectAndWait finished, because: WAIT_OBJECT_0 00000278 0.02677659 [844] ft_stream_receive: LAST frame received: Operation completed, closeing the recieved file. 00000279 0.02682576 [844] finished vortex_cond_wait from vortex_thread.c:919 00000280 0.02689085 [844] xp_request_file: sync queue poped 00000281 0.02697019 [844] xp_request_file: sync queue unrefed 00000282 0.02708445 [844] frame received invocation for second level FINISHED (new task): NUL 4 0 . 716 2 00000283 0.02718586 [844] deallocating frame id=16 00000284 0.02820833 [844] xp_request_file: file transfered, closing file 00000285 0.02828153 [844] invocation frame received handler for channel 4 finished (second level: channel), ref count: channel=2 connection=2 00000286 0.02832706 [844] channel=4 unref called, ref count status after calling=1 00000287 0.02838964 [844] decreased connection id=2 reference count to 1 decreased by second level handler (frame received) 00000288 0.02844970 [844] --> thread from pool waiting for jobs 00000289 0.02850921 [844] called vortex_cond_wait from vortex_thread.c:919 00000290 8.07182121 [2028] xp_send_file: file = client/testfile.dat 00000291 8.07188797 [2028] to_xp_server: message = announce-ft [client-source %client/testfile.dat size 714 key "s1vc.1"] 00000292 8.07197380 [2028] getting mime header size channel->automatic_mime == 1 00000293 8.07204151 [2028] finished checking for MIME configuration=1 for channel=13 00000294 8.07211018 [2028] mime headers size calculated for channel 13 was: 2 00000295 8.07217884 [2028] new message to sent, type=1 channel=13 msgno=2 size (72) = msg size (70) + mime size (2) 00000296 8.07225513 [2028] updating channel sending status to: msgno=2, rpyno=0, seqno=159, ansno=0.. 00000297 8.07233334 [2028] SignalObjectAndWait finished, because: WAIT_OBJECT_0 00000298 8.07242393 [2028] finished vortex_cond_wait from vortex_thread.c:919 00000299 8.07248497 [2028] to_xp_server: getting blocked until reply from xpeers II server arrives. 00000300 8.07259274 [2028] a new message to be sequenced: (channel=13, size=72, sequencer-queue=0).. 00000301 8.07267380 [2028] increased connection id=1 reference to 3 by (vortex sequencer) 00000302 8.07276821 [2028] getting reply at wait reply from the queue 00000303 8.07282448 [2028] sequence operation (0p1231f60): type=1, msgno=2, next seq no=87 message size=72 max seq no=4095 step=0 00000304 8.07287407 [2028] called vortex_cond_timedwait from vortex_thread.c:986 00000305 8.07294464 [2028] the channel is not stalled, continue with sequencing, about to send 72 bytes as payload... 00000306 8.07303619 [2028] sequencing next message: type=1, channel num=13, msgno=2, more=0, next seq=87 size=72 ansno=0 00000307 8.07308483 [2028] frame built, send the frame directly 00000308 8.07315540 [2028] Sending message, size (95) over connection id=1, errno=0 00000309 8.07345581 [844] something to read 00000310 8.07350063 [844] from='get-next' allocating a new frame id=17 00000311 8.07361507 [2028] bytes written: 95 00000312 8.07370567 [2028] write on socket request=95 written=95 00000313 8.07376003 [844] Frame received on channel 13, content type=, transfer encoding=, payload size=72, mime content size=0 00000314 8.07382107 [2028] channel=13 unref called, ref count status after calling=2 00000315 8.07388401 [2028] it seems the message was sent completely 00000316 8.07400608 [2028] channel=13 unref called, ref count status after calling=1 00000317 8.07406616 [844] passed initial accept stage 00000318 8.07410431 [844] passed connection existence stage 00000319 8.07418251 [2028] decreased connection id=1 reference count to 2 decreased by (vortex sequencer) 00000320 8.07423210 [2028] called vortex_cond_wait from vortex_thread.c:919 00000321 8.07432079 [844] SEQ FRAME: not updated, already not consumed half of window advertised: 160 < (4096 / 2) 00000322 8.07434654 [844] frame-content-size=72, frame-payload-size=72, 00000323 8.07440567 [844] window_size=4096, consumed_seqno=159, new_max_seq_no_accepted=4254 00000324 8.07446575 [844] max_seq_no_accepted=4095 00000325 8.07452488 [844] about to checking expected message to be received on this channel 00000326 8.07458401 [844] passed message number checking stage 00000327 8.07467747 [844] updating channel receiving status to: msgno=2, rpyno=0, seqno=159, ansno=0.. 00000328 8.07470322 [844] passed channel update status due to frame received stage 00000329 8.07476139 [844] passed frame checking stage 00000330 8.07481956 [844] found MIME message without headers 00000331 8.07487869 [844] no waiting queue for this message: 2 00000332 8.07493687 [844] it seems you didn't define a second level received handler 00000333 8.07501888 [844] increased connection id=2 reference to 2 by first level handler (frame received) 00000334 8.07508183 [844] SignalObjectAndWait finished, because: WAIT_OBJECT_0 00000335 8.07516956 [844] finished vortex_cond_wait from vortex_thread.c:919 00000336 8.07520485 [844] --> thread from pool processing new job 00000337 8.07527924 [844] frame delivered on first (profile) level handler channel 00000338 8.07532501 [844] xp_ans: connection = 2, channel = 13, profile = http://xpeers.net/xp_msg 00000339 8.07594395 [844] xp_ans: payload = announce-ft [client-source %client/testfile.dat size 714 key "s1vc.1"] 00000340 8.07597065 [844] to_rebol_processor: socket created 00000341 8.07613182 [844] to_rebol_processor: data send, message = xp-ans [id 2 msg announce-ft [client-source %client/testfile.dat size 714 key "s1vc.1"]] 00000342 8.07819557 [844] xp_request_file: target_path = server/testfile.dat, source_file_key = s1vc.1 00000343 8.07825947 [844] xp_request_file: checking profile 0, slice = 1024 00000344 8.07842064 [844] xp_request_file: found FT channel pointer = 011BDFA0 00000345 8.07850647 [844] to_rebol_processor: socket closed 00000346 8.07856560 [844] getting mime header size channel->automatic_mime == 1 00000347 8.07863712 [844] checking channel to be ready (0 == 0) && reply_processed=1 00000348 8.07866287 [844] xp_request_file: channel = 4, using profile 0, slice = 1024 00000349 8.07872581 [844] finished checking for MIME configuration=1 for channel=13 00000350 8.07877254 [844] mime headers size calculated for channel 13 was: 2 00000351 8.07886600 [844] getting mime header size channel->automatic_mime == 1 00000352 8.07892513 [844] finished checking for MIME configuration=1 for channel=4 00000353 8.07898521 [844] new reply message to sent size (12) = msg size (10) + mime size (2) 00000354 8.07904434 [844] mime headers size calculated for channel 4 was: 2 00000355 8.07910442 [844] new message to sent, type=1 channel=4 msgno=1 size (8) = msg size (6) + mime size (2) 00000356 8.07914829 [844] updating channel sending status to: msgno=1, rpyno=0, seqno=15, ansno=0.. 00000357 8.07924271 [844] sending reply for message 2 (size: 10, sequencer queue status: 0, channel queue status: 0) 00000358 8.07926846 [844] updating channel sending status to: msgno=-1, rpyno=3, seqno=36, ansno=0.. 00000359 8.09135723 [844] xp_request_file: sync queue pointer = 011BDBD8 00000360 8.09145260 [844] SignalObjectAndWait finished, because: WAIT_OBJECT_0 00000361 8.09151554 [844] finished vortex_cond_wait from vortex_thread.c:919 00000362 8.09166527 [844] xp_ans: RPY send 00000363 8.09798145 [844] a new message to be sequenced: (channel=4, size=8, sequencer-queue=0).. 00000364 8.09802151 [844] increased connection id=2 reference to 3 by (vortex sequencer) 00000365 8.09811878 [844] invocation frame received handler for channel 13 finished (first level: profiles) 00000366 8.11863232 [844] channel=13 unref called, ref count status after calling=2 00000367 8.11872005 [844] sequence operation (0p10f4b50): type=1, msgno=1, next seq no=7 message size=8 max seq no=4095 step=0 00000368 8.11881638 [844] the channel is not stalled, continue with sequencing, about to send 8 bytes as payload... 00000369 8.11916065 [844] decreased connection id=2 reference count to 2 decreased by first level handler (frame received) 00000370 8.11922550 [844] deallocating frame id=17 00000371 8.11929035 [844] sequencing next message: type=1, channel num=4, msgno=1, more=0, next seq=7 size=8 ansno=0 00000372 8.11933327 [844] --> thread from pool waiting for jobs 00000373 8.12236881 [844] frame built, send the frame directly 00000374 8.12244797 [844] called vortex_cond_wait from vortex_thread.c:919 00000375 8.12413120 [844] Sending message, size (28) over connection id=2, errno=0 00000376 8.12424278 [2028] something to read 00000377 8.12430477 [844] bytes written: 28 00000378 8.12594128 [2028] from='get-next' allocating a new frame id=19 00000379 8.12599659 [844] write on socket request=28 written=28 00000380 8.12605858 [844] channel=4 unref called, ref count status after calling=2 00000381 8.25428009 [2028] Frame received on channel 4, content type=, transfer encoding=, payload size=8, mime content size=0 00000382 8.25434875 [2028] passed initial accept stage 00000383 8.25437450 [2028] passed connection existence stage 00000384 8.25443554 [2028] SEQ FRAME: not updated, already not consumed half of window advertised: 16 < (4096 / 2) 00000385 8.25449467 [2028] frame-content-size=8, frame-payload-size=8, 00000386 8.25455475 [2028] window_size=4096, consumed_seqno=15, new_max_seq_no_accepted=4110 00000387 8.25464725 [2028] max_seq_no_accepted=4095 00000388 8.25470543 [2028] about to checking expected message to be received on this channel 00000389 8.25472927 [2028] passed message number checking stage 00000390 8.25478935 [2028] updating channel receiving status to: msgno=1, rpyno=0, seqno=15, ansno=0.. 00000391 8.25484848 [2028] passed channel update status due to frame received stage 00000392 8.25490570 [2028] passed frame checking stage 00000393 8.25499725 [2028] found MIME message without headers 00000394 8.25505447 [2028] no waiting queue for this message: 1 00000395 8.25507927 [2028] it seems you didn't define a second level received handler 00000396 8.25514507 [2028] increased connection id=1 reference to 3 by first level handler (frame received) 00000397 8.25522232 [2028] SignalObjectAndWait finished, because: WAIT_OBJECT_0 00000398 8.25530910 [2028] finished vortex_cond_wait from vortex_thread.c:919 00000399 8.25538731 [2028] --> thread from pool processing new job 00000400 8.25543785 [2028] frame delivered on first (profile) level handler channel 00000401 8.25574684 [2028] ft_ans_byte: called, message = s1vc.1, msg-number = 1 00000402 8.25580788 [2028] ft_ans_byte: Sending bytes 714 00000403 8.25585842 [2028] getting mime header size channel->automatic_mime == 1 00000404 8.25593662 [2028] something to read 00000405 8.25603580 [2028] finished checking for MIME configuration=1 for channel=4 00000406 8.25606155 [2028] mime headers size calculated for channel 4 was: 2 00000407 8.25617599 [2028] unable to read a line, error was: 10054 Connection reset by peer. An existing connection was forcibly closed by the remote host. This normally results if the peer application on the remote host is suddenly stopped, the host is rebooted, the host or remote network interface is disabled, or the remote host uses a hard close (see setsockopt for more information on the SO_LINGER option on the remote socket). This error may also result if a connection was broken due to keep-alive activity detecting a failure while one or more operations are in progress. Operations that were in progress fail with WSAENETRESET. Subsequent operations fail with WSAECONNRESET. 00000408 8.25620651 [2028] an error have ocurred while reading socket 00000409 8.25629520 [2028] new reply message to sent size (716) = msg size (714) + mime size (2) 00000410 8.25633049 [2028] sending reply for message 1 (size: 714, sequencer queue status: 0, channel queue status: 0) 00000411 8.25642490 [2028] flagging the connection as non-connected 00000412 8.25665283 [2028] closing connection id=1 to 127.0.0.1:44000 00000413 8.25671577 [2028] updating channel sending status to: msgno=-1, rpyno=1, seqno=1434, ansno=1.. 00000414 8.25677490 [2028] closing session id=1 and set to be not connected 00000415 8.25681496 [2028] calling to discard messages pending to be sequenced for connection id=1 00000416 8.25687981 [2028] SignalObjectAndWait finished, because: WAIT_OBJECT_0 00000417 8.25696850 [2028] calling to provide a reference to: 0p1230920 00000418 8.25703335 [2028] flagging to discard pending message to be sequenced for connection id=1 00000419 8.25707436 [2028] ft_ans_byte: Sending bytes 0 00000420 8.25710869 [2028] decreased connection id=1 reference count to 2 decreased by vortex reader (process) 00000421 8.25716686 [2028] received a reply request to be sent over a non connected session, dropming message 00000422 8.25725365 [2028] finished vortex_cond_wait from vortex_thread.c:919 00000423 8.25733089 [2028] a new message to be sequenced: (channel=4, size=716, sequencer-queue=0).. 00000424 8.25738716 [2028] ft_ans_byte: There was an error while sending the last NUL reply message 00000425 8.25744629 [2028] no more connection to watch for, putting into sleep thread 00000426 8.25750637 [2028] ft_ans_byte: end task (pid: 2028), bytes transferred: 714 (ans/nul pattern) 00000427 8.25754738 [2028] discarding sequencer data (found flag activated) 00000428 8.25759125 [2028] called vortex_cond_wait from vortex_thread.c:919 00000429 8.25767994 [2028] channel=4 unref called, ref count status after calling=2 00000430 8.25771332 [2028] decreased connection id=1 reference count to 1 decreased by first level handler (frame received) 00000431 8.25777340 [2028] channel=4 unref called, ref count status after calling=1 00000432 8.25785542 [2028] deallocating frame id=19 00000433 8.25789165 [2028] --> thread from pool waiting for jobs 00000434 8.25794983 [2028] called vortex_cond_wait from vortex_thread.c:919 00000435 8.25802612 [2028] called vortex_cond_wait from vortex_thread.c:919