[OpenSIPS-Users] OpenSIPS returns 400 Bad Request for PUBLISH

[Saúl Ibarra]

Error messages are quite descriptive ;) You've tried to record_route
that PUBLISH request twice... and also the content length it's zero so
what does that PUBLISH actulally 'mean'?

Maybe if you show us some little piece of your script (the one andling
the publish stuff) we could help you on the first error.


On Wed, Oct 14, 2009 at 7:19 AM, Sanjeev BA <as2902.b at samsung.com> wrote:
> Error logs from OpenSIPS console.
>
>
>
> Oct 14 14:01:46 [4880] DBG:core:parse_msg:  method:  <PUBLISH>
>
> Oct 14 14:01:46 [4880] DBG:core:parse_msg:  uri:
> <sip:tester at imsdemo.com>
>
> Oct 14 14:01:46 [4880] DBG:core:parse_msg:  version: <SIP/2.0>
>
> Oct 14 14:01:46 [4880] DBG:core:parse_headers: flags=2
>
> Oct 14 14:01:46 [4880] DBG:core:get_hdr_field: cseq <CSeq>: <1> <PUBLISH>
>
> Oct 14 14:01:46 [4880] DBG:core:parse_to: end of header reached, state=10
>
> Oct 14 14:01:46 [4880] DBG:core:parse_to: display={},
> ruri={sip:tester at imsdemo.com}
>
> Oct 14 14:01:46 [4880] DBG:core:get_hdr_field: <To> [27];
> uri=[sip:tester at imsdemo.com]
>
> Oct 14 14:01:46 [4880] DBG:core:get_hdr_field: to body
> [<sip:tester at imsdemo.com>
>
> ]
>
> Oct 14 14:01:46 [4880] DBG:core:parse_via_param: found param type 232,
> <branch> = <z9hG4bK2559870494smg>; state=6
>
> Oct 14 14:01:46 [4880] DBG:core:parse_via_param: found param type 238,
> <transport> = <UDP>; state=16
>
> Oct 14 14:01:46 [4880] DBG:core:parse_via: end of header reached, state=5
>
> Oct 14 14:01:46 [4880] DBG:core:parse_headers: via found, flags=2
>
> Oct 14 14:01:46 [4880] DBG:core:parse_headers: this is the first via
>
> Oct 14 14:01:46 [4880] DBG:core:receive_msg: After parse_msg...
>
> Oct 14 14:01:46 [4880] DBG:core:receive_msg: preparing to run routing
> scripts...
>
> Oct 14 14:01:46 [4880] DBG:maxfwd:is_maxfwd_present: value = 70
>
> Oct 14 14:01:46 [4880] DBG:core:parse_headers: flags=80
>
> Oct 14 14:01:46 [4880] DBG:uri:has_totag: no totag
>
> Oct 14 14:01:46 [4880] DBG:core:parse_headers: flags=78
>
> Oct 14 14:01:46 [4880] DBG:tm:t_lookup_request: start searching: hash=30511,
> isACK=0
>
> Oct 14 14:01:46 [4880] DBG:tm:matching_3261: RFC3261 transaction matching
> failed
>
> Oct 14 14:01:46 [4880] DBG:tm:t_lookup_request: no transaction found
>
> Oct 14 14:01:46 [4880] DBG:core:parse_headers: flags=200
>
> Oct 14 14:01:46 [4880] DBG:core:get_hdr_field: content_length=0
>
> Oct 14 14:01:46 [4880] DBG:core:get_hdr_field: found end of header
>
> Oct 14 14:01:46 [4880] DBG:rr:find_first_route: No Route headers found
>
> Oct 14 14:01:46 [4880] DBG:rr:loose_route: There is no Route HF
>
> Oct 14 14:01:46 [4880] ERROR:rr:w_record_route: Double attempt to
> record-route
>
> Oct 14 14:01:46 [4880] DBG:core:grep_sock_info: checking if host==us: 11==12
> &&  [imsdemo.com] == [10.89.10.235]
>
> Oct 14 14:01:46 [4880] DBG:core:grep_sock_info: checking if port 5060
> matches port 5060
>
> Oct 14 14:01:46 [4880] DBG:core:parse_headers: flags=ffffffffffffffff
>
> Oct 14 14:01:46 [4880] DBG:presence:search_event: start event= [presence]
>
> Oct 14 14:01:46 [4880] DBG:presence:handle_publish: SIP-If-Match header not
> found
>
> Oct 14 14:01:46 [4880] DBG:presence:generate_ETag: etag=
> a.1255496470.4880.1.0 / 21
>
> Oct 14 14:01:46 [4880] DBG:presence:handle_publish: new etag  =
> a.1255496470.4880.1.0
>
> Oct 14 14:01:46 [4880] DBG:presence:handle_publish: Expires header found,
> value= 3600
>
> Oct 14 14:01:46 [4880] ERROR:presence:handle_publish: No E-Tag and no body
> found
>
> Oct 14 14:01:46 [4880] DBG:core:parse_headers: flags=ffffffffffffffff
>
> Oct 14 14:01:46 [4880] DBG:core:check_via_address: params 10.254.140.195,
> 10.254.140.195, 0
>
> Oct 14 14:01:46 [4880] DBG:sl:run_sl_callbacks: callback id 0 entered
>
> Oct 14 14:01:46 [4880] DBG:tm:t_newtran: transaction on entrance=(nil)
>
> Oct 14 14:01:46 [4880] DBG:core:parse_headers: flags=ffffffffffffffff
>
> Oct 14 14:01:46 [4880] DBG:core:parse_headers: flags=78
>
> Oct 14 14:01:46 [4880] DBG:tm:t_lookup_request: start searching: hash=30511,
> isACK=0
>
> Oct 14 14:01:46 [4880] DBG:tm:matching_3261: RFC3261 transaction matching
> failed
>
> Oct 14 14:01:46 [4880] DBG:tm:t_lookup_request: no transaction found
>
> Oct 14 14:01:46 [4880] DBG:tm:run_reqin_callbacks: trans=0xb3a09a30,
> callback type 1, id 0 entered
>
> Oct 14 14:01:46 [4880] DBG:tm:cleanup_uac_timers: RETR/FR timers reset
>
> Oct 14 14:01:46 [4880] DBG:tm:insert_timer_unsafe: [2]: 0xb3a09a78 (41)
>
> Oct 14 14:01:46 [4880] DBG:tm:t_unref: UNREF_UNSAFE: after is 0
>
> Oct 14 14:01:46 [4880] DBG:core:destroy_avp_list: destroying list (nil)
>
> Oct 14 14:01:46 [4880] DBG:core:receive_msg: cleaning up
>
> Oct 14 14:01:51 [4885] DBG:tm:timer_routine: timer routine:2,tl=0xb3a09a78
> next=(nil), timeout=41
>
> Oct 14 14:01:51 [4885] DBG:tm:wait_handler: removing 0xb3a09a30 from table
>
> Oct 14 14:01:51 [4885] DBG:tm:delete_cell: delete transaction 0xb3a09a30
>
> Oct 14 14:01:51 [4885] DBG:tm:wait_handler: done
>
> Oct 14 14:02:50 [4885] DBG:presence:update_db_subs: delete expired
>
> Oct 14 14:02:50 [4885] DBG:db_mysql:db_mysql_do_prepared_query:
> conn=0x8167ee8 (tail=135699504) MC=0x816ba48
>
> Oct 14 14:02:50 [4885] DBG:db_mysql:db_mysql_do_prepared_query: new
> query=|delete from active_watchers where expires<?|
>
> Oct 14 14:02:50 [4885] DBG:db_mysql:db_mysql_do_prepared_query: new
> statement(0x8169f70) on connection: (0x8167ee8) 0x8169c30
>
> Oct 14 14:02:50 [4885] DBG:db_mysql:db_mysql_do_prepared_query: set values
> for the statement run
>
> Oct 14 14:02:50 [4885] DBG:db_mysql:db_mysql_val2bind: added val (0): len=4;
> type=3; is_null=0
>
> Oct 14 14:02:50 [4885] DBG:db_mysql:db_mysql_do_prepared_query: doing
> BIND_PARAM in...
>
> Oct 14 14:02:50 [4885] DBG:presence:msg_watchers_clean: cleaning pending
> subscriptions
>
> Oct 14 14:02:50 [4885] DBG:core:db_do_query: SYNC-DBG - SELECT successfully
> executed!
>
>
>
>
>
> Kindly advice.
>
>
>
> Regards
>
> Sanjeev
>
>
>
>
>
> Hi,
>
>
>
> I am observing an error response from OpenSIPS. It returns 400 Bad Request
> for the following PUBLISH request.
>
>
>
> PUBLISH sip:tester at imsdemo.com SIP/2.0
>
> Expires: 3600
>
> Event: presence
>
> Privacy: None
>
> Accept-Contact: *;+g.3gpp.Pua;explicit
>
> Contact:
> sip:tester at 10.10.10.20
>
> Call-ID: 2189952363 at imsdemo.com
>
> CSeq: 1 PUBLISH
>
> Max-Forwards: 70
>
> From: <sip:tester at imsdemo.com>;tag=1842963402
>
> To: <sip:tester at imsdemo.com>
>
> Via:SIP/2.0/UDP 10.254.140.195:5060;branch=z9hG4bK132770389smg;transport=UDP
>
> Content-Length: 0
>
>
>
>
>
> Regards,
>
> Sanjeev
>
> _______________________________________________
> Users mailing list
> Users at lists.opensips.org
> http://lists.opensips.org/cgi-bin/mailman/listinfo/users
>
>



-- 
/Saúl
http://www.saghul.net | http://www.sipdoc.net