Thanks for your response,
Sorry, I didn't include the code for debug string. I set back the position
after getting the debug trace. Following is the code for that.
I check, the '3284', is actually coming from previous buffer. I include the
complete trace from previous trace as below:
The code is quite messy right now, I'm putting a lot of debugging log just
to troubleshoot this problem :)
btw, I'm using mina 1.1.6.
Rgds,
Johny K.
================================
private String getBufferString(ByteBuffer in) {
int size = in.remaining();
if (size == 0) {
return "empty";
}
StringBuffer out = new StringBuffer((in.remaining() * 3) - 1);
int mark = in.position();
// and the others, too
for (; size > 0; size--) {
out.append((char) in.get());
}
in.position(mark);
return out.toString();
}
==============================
0:27:55,867 [AnonymousIoService-1] DEBUG FSResponseDecoder - Found
content-length index at 0
10:27:55,867 [AnonymousIoService-1] DEBUG FSResponseDecoder - [ ]
10:27:55,867 [AnonymousIoService-1] DEBUG FSResponseDecoder - [3]
10:27:55,867 [AnonymousIoService-1] DEBUG FSResponseDecoder - [2]
10:27:55,867 [AnonymousIoService-1] DEBUG FSResponseDecoder - [8]
10:27:55,867 [AnonymousIoService-1] DEBUG FSResponseDecoder - [4]
10:27:55,867 [AnonymousIoService-1] DEBUG FSResponseDecoder - ***** Buffer
in getContentLength 2 *****
Content-Length: 3284
Content-Type: text/event-plain
Channel-State: CS_EXECUTE
Channel-State-Number: 4
Channel-Name: sofia/external/nobody%40192.168.3.12
Unique-ID: fd04ead6-2d6c-11dd-9acd-0b28d09a52aa
Call-Direction: inbound
Answer-State: answered
Channel-Read-Codec-Name: PCMU
Channel-Read-Codec-Rate: 8000
Channel-Write-Codec-Name: PCMU
Channel-Write-Codec-Rate: 8000
Caller-Dialplan: XML
Caller-Network-Addr: 192.168.3.12
Caller-Destination-Number: 6601
Caller-Unique-ID: fd04ead6-2d6c-11dd-9acd-0b28d09a52aa
Caller-Source: mod_sofia
Caller-Context: default
Caller-RDNIS: 6601
Caller-Channel-Name: sofia/external/nobody%40192.168.3.12
Caller-Profile-Index: 2
Caller-Channel-Created-Time: 1212058201566175
Caller-Channel-Answered-Time: 1212058201640001
Caller-Channel-Hangup-Time: 0
Caller-Channel-Transfer-Time: 0
Caller-Screen-Bit: yes
Caller-Privacy-Hide-Name: no
Caller-Privacy-Hide-Number: no
variable_sip_from_user: nobody
variable_sip_from_uri: nobody%40192.168.3.12
variable_sip_from_host: 192.168.3.12
variable_sip_from_tag: ZSrg0c8tH35Xa
variable_sofia_profile_name: external
variable_sofia_profile_domain_name: external
variable_sip_req_user: 6601
variable_sip_req_port: 5080
variable_sip_req_uri: 6601%40192.168.3.11%3A5080
variable_sip_req_host: 192.168.3.11
variable_sip_to_user: 6601
variable_sip_to_port: 5080
variable_sip_to_uri: 6601%40192.168.3.11%3A5080
variable_sip_to_host: 192.168.3.11
variable_sip_contact_user: mod_sofia
variable_sip_contact_port: 5060
variable_sip_contact_uri: mod_sofia%40192.168.3.12%3A5060
variable_sip_contact_host: 192.168.3.12
variable_channel_name: sofia/external/nobody%40192.168.3.12
variable_sip_call_id: 8232379f-a82e-122b-8485-000f1f644b48
variable_sip_user_agent: FreeSWITCH-mod_sofia/1.0.pre4-8539
variable_sip_via_host: 192.168.3.12
variable_sip_via_rport: 5060
variable_switch_r_sdp:
v%3D0%0D%0Ao%3DFreeSWITCH%208268952646319231016%205951282259024528182%20IN%20IP4%20192.168.3.12%0D%0As%3DFreeSWITCH%0D%0Ac%3DIN%20IP4%20192.168.3.12%0D%0At%3D0%200%0D%0Aa%3Dsendrecv%0D%0Am%3Daudio%2028556%20RTP/AVP%209%200%208%203%20101%2013%0D%0Aa%3Drtpmap%3A9%20G722/8000%0D%0Aa%3Drtpmap%3A0%20PCMU/8000%0D%0Aa%3Drtpmap%3A8%20PCMA/8000%0D%0Aa%3Drtpmap%3A3%20GSM/8000%0D%0Aa%3Drtpmap%3A101%20telephone-event/8000%0D%0Aa%3Dfmtp%3A101%200-16%0D%0Aa%3Drtpmap%3A13%20CN/8000%0D%0Aa%3Dptime%3A20%0D%0A
variable_remote_media_ip: 192.168.3.12
variable_remote_media_port: 28556
variable_read_codec: PCMU
variable_read_rate: 8000
variable_write_codec: PCMU
variable_write_rate: 8000
variable_max_forwards: 69
variable_use_profile: nat
variable_numbering_plan: US
variable_default_gateway: asterlink.com
variable_default_area_code: 918
variable_user_name: default
variable_domain_name: 192.168.3.11
variable_local_media_ip: 192.168.3.11
variable_local_media_port: 28556
variable_endpoint_disposition: ANSWER
Application: playback
Application-Data: swn/connecting-1.wav
Event-Name: CHANNEL_EXECUTE
Core-UUID: ed9888ba-2c94-11dd-9acd-0b28d09a52aa
FreeSWITCH-Hostname: COADAIN01
FreeSWITCH-IPv4: 192.168.3.11
FreeSWITCH-IPv6: 127.0.0.1
Event-Date-Local: 2008-05-29%2006%3A50%3A01
Event-Date-GMT: Thu,%2029%20May%202008%2010%3A50%3A01%20GMT
Event-Date-timestamp: 1212058201641033
Event-Calling-File: switch_core_session.c
Event-Calling-Function: switch_core_session_exec
Event-Calling-Line-Number: 1033
Content-Length: 1619
Content-Type: text/event-plain
Channel-State: CS_NEW
Channel-State-Number: 0
Channel-Name: sofia/external/nobody%40192.168.3.12
Unique-ID: fd2229c0-2d6c-11dd-9acd-0b28d09a52aa
Call-Direction: inbound
Answer-State: ringing
variable_sip_from_user: nobody
variable_sip_from_uri: nobody%40192.168.3.12
variable_sip_from_host: 192.168.3.12
variable_sip_from_tag: 02H917ryecvgp
variable_sofia_profile_name: external
variable_sofia_profile_domain_name: external
variable_sip_req_user: 6001
variable_sip_req_port: 5080
variable_sip_req_uri: 6001%40192.168.3.11%3A5080
variable_sip_req_host: 192.168.3.11
variable_sip_to_user: 6001
variable_sip_to_port: 5080
variable_sip_to_uri: 6001%40192.168.3.11%3A5080
variable_sip_to_host: 192.168.3.11
variable_sip_contact_user: mod_sofia
variable_sip_contact_port: 5060
variable_sip_contact_uri: mod_sofia%40192.168.3.12%3A5060
variable_sip_contact_host: 192.168.3.12
variable_channel_name: sofia/external/nobody%40192.168.3.12
variable_endpoint_disposition: INBOUND%20CALL
variable_sip_call_id: 824f7531-a82e-122b-8485-000f1f644b48
variable_sip_user_agent: FreeSWITCH-mod_sofia/1.0.pre4-8539
variable_sip_via_host: 192.168.3.12
variable_sip_via_rport: 5060
variable_max_forwards: 70
Event-Name: CHANNEL_CREATE
Core-UUID: ed9888ba-2c94-11dd-
10:27:55,867 [AnonymousIoService-1] DEBUG FSResponseDecoder - ContentLength
= 3284
10:27:55,867 [AnonymousIoService-1] DEBUG FSResponseDecoder - total buffer
length = 4632
10:27:55,867 [AnonymousIoService-1] DEBUG FSResponseDecoder - Parsing
request with sizeToRead = 3337
10:27:55,867 [AnonymousIoService-1] DEBUG FSResponseDecoder - Reading
parameters:
10:27:55,867 [AnonymousIoService-1] DEBUG FSResponseDecoder -
Content-Length: 3284
10:27:55,867 [AnonymousIoService-1] DEBUG FSResponseDecoder - Content-Type:
text/event-plain
10:27:55,867 [AnonymousIoService-1] DEBUG FSResponseDecoder - ]]]]] Finish
decode function on session (SOCKET, R: /192.168.3.11:8021, L: /
192.168.150.52:4621, S: /192.168.3.11:8021)
10:27:55,867 [AnonymousIoService-1] DEBUG FSResponseDecoder - ***** New
Buffer to analyze *****
10:27:55,867 [AnonymousIoService-1] DEBUG FSResponseDecoder - Buffer Dump
Content-Length: 1619
Content-Type: text/event-plain
Channel-State: CS_NEW
Channel-State-Number: 0
Channel-Name: sofia/external/nobody%40192.168.3.12
Unique-ID: fd2229c0-2d6c-11dd-9acd-0b28d09a52aa
Call-Direction: inbound
Answer-State: ringing
variable_sip_from_user: nobody
variable_sip_from_uri: nobody%40192.168.3.12
variable_sip_from_host: 192.168.3.12
variable_sip_from_tag: 02H917ryecvgp
variable_sofia_profile_name: external
variable_sofia_profile_domain_name: external
variable_sip_req_user: 6001
variable_sip_req_port: 5080
variable_sip_req_uri: 6001%40192.168.3.11%3A5080
variable_sip_req_host: 192.168.3.11
variable_sip_to_user: 6001
variable_sip_to_port: 5080
variable_sip_to_uri: 6001%40192.168.3.11%3A5080
variable_sip_to_host: 192.168.3.11
variable_sip_contact_user: mod_sofia
variable_sip_contact_port: 5060
variable_sip_contact_uri: mod_sofia%40192.168.3.12%3A5060
variable_sip_contact_host: 192.168.3.12
variable_channel_name: sofia/external/nobody%40192.168.3.12
variable_endpoint_disposition: INBOUND%20CALL
variable_sip_call_id: 824f7531-a82e-122b-8485-000f1f644b48
variable_sip_user_agent: FreeSWITCH-mod_sofia/1.0.pre4-8539
variable_sip_via_host: 192.168.3.12
variable_sip_via_rport: 5060
variable_max_forwards: 70
Event-Name: CHANNEL_CREATE
Core-UUID: ed9888ba-2c94-11dd-
10:27:55,867 [AnonymousIoService-1] DEBUG FSResponseDecoder - last = 1294
10:27:55,867 [AnonymousIoService-1] DEBUG FSResponseDecoder - ***** Buffer
in getContentLength 1 *****
Content-Length: 1619
Content-Type: text/event-plain
Channel-State: CS_NEW
Channel-State-Number: 0
Channel-Name: sofia/external/nobody%40192.168.3.12
Unique-ID: fd2229c0-2d6c-11dd-9acd-0b28d09a52aa
Call-Direction: inbound
Answer-State: ringing
variable_sip_from_user: nobody
variable_sip_from_uri: nobody%40192.168.3.12
variable_sip_from_host: 192.168.3.12
variable_sip_from_tag: 02H917ryecvgp
variable_sofia_profile_name: external
variable_sofia_profile_domain_name: external
variable_sip_req_user: 6001
variable_sip_req_port: 5080
variable_sip_req_uri: 6001%40192.168.3.11%3A5080
variable_sip_req_host: 192.168.3.11
variable_sip_to_user: 6001
variable_sip_to_port: 5080
variable_sip_to_uri: 6001%40192.168.3.11%3A5080
variable_sip_to_host: 192.168.3.11
variable_sip_contact_user: mod_sofia
variable_sip_contact_port: 5060
variable_sip_contact_uri: mod_sofia%40192.168.3.12%3A5060
variable_sip_contact_host: 192.168.3.12
variable_channel_name: sofia/external/nobody%40192.168.3.12
variable_endpoint_disposition: INBOUND%20CALL
variable_sip_call_id: 824f7531-a82e-122b-8485-000f1f644b48
variable_sip_user_agent: FreeSWITCH-mod_sofia/1.0.pre4-8539
variable_sip_via_host: 192.168.3.12
variable_sip_via_rport: 5060
variable_max_forwards: 70
Event-Name: CHANNEL_CREATE
Core-UUID: ed9888ba-2c94-11dd-
10:27:55,867 [AnonymousIoService-1] DEBUG FSResponseDecoder - Found
content-length index at 0
10:27:55,867 [AnonymousIoService-1] DEBUG FSResponseDecoder - [ ]
10:27:55,867 [AnonymousIoService-1] DEBUG FSResponseDecoder - [3]
10:27:55,867 [AnonymousIoService-1] DEBUG FSResponseDecoder - [2]
10:27:55,867 [AnonymousIoService-1] DEBUG FSResponseDecoder - [8]
10:27:55,867 [AnonymousIoService-1] DEBUG FSResponseDecoder - [4]
10:27:55,867 [AnonymousIoService-1] DEBUG FSResponseDecoder - ***** Buffer
in getContentLength 2 *****
Content-Length: 1619
Content-Type: text/event-plain
Channel-State: CS_NEW
Channel-State-Number: 0
Channel-Name: sofia/external/nobody%40192.168.3.12
Unique-ID: fd2229c0-2d6c-11dd-9acd-0b28d09a52aa
Call-Direction: inbound
Answer-State: ringing
variable_sip_from_user: nobody
variable_sip_from_uri: nobody%40192.168.3.12
variable_sip_from_host: 192.168.3.12
variable_sip_from_tag: 02H917ryecvgp
variable_sofia_profile_name: external
variable_sofia_profile_domain_name: external
variable_sip_req_user: 6001
variable_sip_req_port: 5080
variable_sip_req_uri: 6001%40192.168.3.11%3A5080
variable_sip_req_host: 192.168.3.11
variable_sip_to_user: 6001
variable_sip_to_port: 5080
variable_sip_to_uri: 6001%40192.168.3.11%3A5080
variable_sip_to_host: 192.168.3.11
variable_sip_contact_user: mod_sofia
variable_sip_contact_port: 5060
variable_sip_contact_uri: mod_sofia%40192.168.3.12%3A5060
variable_sip_contact_host: 192.168.3.12
variable_channel_name: sofia/external/nobody%40192.168.3.12
variable_endpoint_disposition: INBOUND%20CALL
variable_sip_call_id: 824f7531-a82e-122b-8485-000f1f644b48
variable_sip_user_agent: FreeSWITCH-mod_sofia/1.0.pre4-8539
variable_sip_via_host: 192.168.3.12
variable_sip_via_rport: 5060
variable_max_forwards: 70
Event-Name: CHANNEL_CREATE
Core-UUID: ed9888ba-2c94-11dd-
10:27:55,867 [AnonymousIoService-1] DEBUG FSResponseDecoder - ContentLength
= 3284
10:27:55,867 [AnonymousIoService-1] DEBUG FSResponseDecoder - total buffer
length = 1295
10:27:55,867 [AnonymousIoService-1] DEBUG FSResponseDecoder -
content_length[3284] + eoh[52] == in.remaining[1295] ==> false
10:27:55,867 [AnonymousIoService-1] INFO FSProtocolHandler - [/
192.168.3.11:8021] RECEIVED:
On Thu, May 29, 2008 at 11:36 AM, Emmanuel Lecharny <[EMAIL PROTECTED]>
wrote:
> Hi,
>
> are you sure you flip the ByteBuffer after having dumped it in the debug
> trace ? It's a ByteBuffer, so each time you read a byte, the position is
> incremented, and won't come back to the original position.
>
> I guess that the length (3284) is just the next 4 bytes after the last line
> printed in debug mode :
>
> Core-UUID: ed9888ba-2c94-11dd- [3284...]
>
> Can you check that ?
>
>
>
>
> Johny Kadarisman wrote:
>
>> Hi, I found anomaly, that yet to find what went wrong on these ByteBuffer?
>>
>> I'm trying to decode a specific switch protocol, that based on
>> content-length information. So following is from my decoder class that
>> trying to search the length from 'in' buffer.
>>
>> Attached is the log output from last run, here you can before doing
>> anything, The buffer dump show content-length of "1619". Then I continue
>> with logic to parse this into integer, with in.get(i) methods. But, from
>> this methods, it return '3284'. Which, I believe from previous buffer.
>> Now,
>> At the end of these routines, I dump again this 'in' bytebuffer. This
>> time,
>> it still showing the content-length of '1619'. After this, the subsequent
>> protocol parsing is getting screw, since the length is not chop properly.
>>
>> This symptom occurs on high load messages from the server, during low
>> load,
>> everything seems fine.
>>
>> Anybody encounter similar problem? your hints is appreciated.
>>
>> Thanks,
>> Johny K.
>>
>>
>> ================================================================
>>
>>
>> private int getContentLength(ByteBuffer in, int last) {
>>
>> String str = getBufferString(in); // in.getHexDump();
>> logger.debug("last = "+last);
>> logger.debug("***** Buffer in getContentLength 1 *****\n"+str);
>>
>> for (int i = 0; i < last; i++) {
>> boolean found = false;
>> for (int j = 0; j < CONTENT_LENGTH.length; j++) {
>> if (in.get(i + j) != CONTENT_LENGTH[j]) {
>> found = false;
>> break;
>> }
>> found = true;
>> }
>> if (found) {
>> // retrieve value from this position till next 0x0D 0x0A
>> logger.debug("Found content-length index at "+i);
>>
>> StringBuilder contentLength = new StringBuilder();
>> for (int j = i + CONTENT_LENGTH.length; j < last; j++) {
>> if (in.get(j) == 0x0A)
>> break;
>> contentLength.append(new String( new byte[] { in.get(j)
>> }));
>> logger.debug("["+new String( new byte[]
>> {in.get(j)})+"]");
>> }
>> // if content-length worth of data has been received then
>> the message is complete
>>
>> str = getBufferString(in); //
>> in.getHexDump();
>> logger.debug("***** Buffer in getContentLength 2
>> *****\n"+str);
>>
>> logger.debug("ContentLength = "+contentLength);
>> logger.debug("total buffer length = "+in.remaining());
>> return Integer.parseInt(contentLength.toString().trim());
>> }
>> }
>> return -1;
>> }
>>
>>
>>
>>
>>
>>
>>
>> 10:27:55,867 [AnonymousIoService-1] DEBUG FSResponseDecoder - *****
>> Buffer
>> in getContentLength 1 *****
>> Content-Length: 1619
>> Content-Type: text/event-plain
>>
>> Channel-State: CS_NEW
>> Channel-State-Number: 0
>> Channel-Name: sofia/external/nobody%40192.168.3.12
>> Unique-ID: fd2229c0-2d6c-11dd-9acd-0b28d09a52aa
>> Call-Direction: inbound
>> Answer-State: ringing
>> variable_sip_from_user: nobody
>> variable_sip_from_uri: nobody%40192.168.3.12
>> variable_sip_from_host: 192.168.3.12
>> variable_sip_from_tag: 02H917ryecvgp
>> variable_sofia_profile_name: external
>> variable_sofia_profile_domain_name: external
>> variable_sip_req_user: 6001
>> variable_sip_req_port: 5080
>> variable_sip_req_uri: 6001%40192.168.3.11%3A5080
>> variable_sip_req_host: 192.168.3.11
>> variable_sip_to_user: 6001
>> variable_sip_to_port: 5080
>> variable_sip_to_uri: 6001%40192.168.3.11%3A5080
>> variable_sip_to_host: 192.168.3.11
>> variable_sip_contact_user: mod_sofia
>> variable_sip_contact_port: 5060
>> variable_sip_contact_uri: mod_sofia%40192.168.3.12%3A5060
>> variable_sip_contact_host: 192.168.3.12
>> variable_channel_name: sofia/external/nobody%40192.168.3.12
>> variable_endpoint_disposition: INBOUND%20CALL
>> variable_sip_call_id: 824f7531-a82e-122b-8485-000f1f644b48
>> variable_sip_user_agent: FreeSWITCH-mod_sofia/1.0.pre4-8539
>> variable_sip_via_host: 192.168.3.12
>> variable_sip_via_rport: 5060
>> variable_max_forwards: 70
>> Event-Name: CHANNEL_CREATE
>> Core-UUID: ed9888ba-2c94-11dd-
>> 10:27:55,867 [AnonymousIoService-1] DEBUG FSResponseDecoder - Found
>> content-length index at 0
>> 10:27:55,867 [AnonymousIoService-1] DEBUG FSResponseDecoder - [ ]
>> 10:27:55,867 [AnonymousIoService-1] DEBUG FSResponseDecoder - [3]
>> 10:27:55,867 [AnonymousIoService-1] DEBUG FSResponseDecoder - [2]
>> 10:27:55,867 [AnonymousIoService-1] DEBUG FSResponseDecoder - [8]
>> 10:27:55,867 [AnonymousIoService-1] DEBUG FSResponseDecoder - [4]
>> 10:27:55,867 [AnonymousIoService-1] DEBUG FSResponseDecoder - *****
>> Buffer
>> in getContentLength 2 *****
>> Content-Length: 1619
>> Content-Type: text/event-plain
>>
>> Channel-State: CS_NEW
>> Channel-State-Number: 0
>> Channel-Name: sofia/external/nobody%40192.168.3.12
>> Unique-ID: fd2229c0-2d6c-11dd-9acd-0b28d09a52aa
>> Call-Direction: inbound
>> Answer-State: ringing
>> variable_sip_from_user: nobody
>> variable_sip_from_uri: nobody%40192.168.3.12
>> variable_sip_from_host: 192.168.3.12
>> variable_sip_from_tag: 02H917ryecvgp
>> variable_sofia_profile_name: external
>> variable_sofia_profile_domain_name: external
>> variable_sip_req_user: 6001
>> variable_sip_req_port: 5080
>> variable_sip_req_uri: 6001%40192.168.3.11%3A5080
>> variable_sip_req_host: 192.168.3.11
>> variable_sip_to_user: 6001
>> variable_sip_to_port: 5080
>> variable_sip_to_uri: 6001%40192.168.3.11%3A5080
>> variable_sip_to_host: 192.168.3.11
>> variable_sip_contact_user: mod_sofia
>> variable_sip_contact_port: 5060
>> variable_sip_contact_uri: mod_sofia%40192.168.3.12%3A5060
>> variable_sip_contact_host: 192.168.3.12
>> variable_channel_name: sofia/external/nobody%40192.168.3.12
>> variable_endpoint_disposition: INBOUND%20CALL
>> variable_sip_call_id: 824f7531-a82e-122b-8485-000f1f644b48
>> variable_sip_user_agent: FreeSWITCH-mod_sofia/1.0.pre4-8539
>> variable_sip_via_host: 192.168.3.12
>> variable_sip_via_rport: 5060
>> variable_max_forwards: 70
>> Event-Name: CHANNEL_CREATE
>> Core-UUID: ed9888ba-2c94-11dd-
>> 10:27:55,867 [AnonymousIoService-1] DEBUG FSResponseDecoder -
>> ContentLength
>> = 3284
>> 10:27:55,867 [AnonymousIoService-1] DEBUG FSResponseDecoder - total
>> buffer
>> length = 1295
>>
>>
>>
>
>
> --
> --
> cordialement, regards,
> Emmanuel Lécharny
> www.iktek.com
> directory.apache.org
>
>
>
