Dispatcher probing fails to match a 405 reply code.

[NormB]

A carrier (LEVEL3) responds to dispatcher OPTIONS requests with a 405 Method Not Allowed.

Added 405 to the list of options_reply_codes as follows: modparam("dispatcher", "options_reply_codes", "501, 405, 403, 200")

The destinations receiving the 405's continued to remain in a pending state.

Debug logging was turned on and a portion of it is copied below. Internally, OpenSIPS thinks that the result of the OPTIONS was a 408, NOT a 405.

Success was achieved by adding 408 to the list of options_reply_codes.

Jul 31 20:07:11 13cn8 /usr/local/opensips/sbin/opensips[4537]: DBG:tm:local_reply: branch=0, save=0, winner=0
Jul 31 20:07:11 13cn8 /usr/local/opensips/sbin/opensips[4537]: DBG:tm:local_reply: local transaction completed
Jul 31 20:07:11 13cn8 /usr/local/opensips/sbin/opensips[4537]: DBG:tm:run_trans_callbacks: trans=0x7f1527524a70, callback type 256, id 0 entered
Jul 31 20:07:11 13cn8 /usr/local/opensips/sbin/opensips[4537]: DBG:dispatcher:ds_options_callback: OPTIONS-Request was finished with code 408 (to sip:4.55.19.33:5060, group 2)
Jul 31 20:07:11 13cn8 /usr/local/opensips/sbin/opensips[4537]: DBG:dispatcher:ds_set_state: no event sent
Jul 31 20:07:11 13cn8 /usr/local/opensips/sbin/opensips[4537]: DBG:tm:insert_timer_unsafe: [2]: 0x7f1527524af0 (65)
Jul 31 20:07:11 13cn8 /usr/local/opensips/sbin/opensips[4537]: DBG:tm:final_response_handler: done
Jul 31 20:07:11 13cn8 /usr/local/opensips/sbin/opensips[4537]: DBG:tm:timer_routine: timer routine:0,tl=0x7f15275284a0 next=0x7f152752bc80, timeout=60
Jul 31 20:07:11 13cn8 /usr/local/opensips/sbin/opensips[4537]: DBG:tm:final_response_handler: Cancel sent out, sending 408 (0x7f1527528250)
Jul 31 20:07:11 13cn8 /usr/local/opensips/sbin/opensips[4537]: DBG:tm:t_should_relay_response: T_code=0, new_code=408
Jul 31 20:07:11 13cn8 /usr/local/opensips/sbin/opensips[4537]: DBG:tm:t_pick_branch: picked branch 0, code 408 (prio=800)
Jul 31 20:07:11 13cn8 /usr/local/opensips/sbin/opensips[4537]: DBG:tm:local_reply: branch=0, save=0, winner=0
Jul 31 20:07:11 13cn8 /usr/local/opensips/sbin/opensips[4537]: DBG:tm:local_reply: local transaction completed
Jul 31 20:07:11 13cn8 /usr/local/opensips/sbin/opensips[4537]: DBG:tm:run_trans_callbacks: trans=0x7f1527528250, callback type 256, id 0 entered
Jul 31 20:07:11 13cn8 /usr/local/opensips/sbin/opensips[4537]:

U 4.55.23.33:5060 -> 198.1.55.123:5060
SIP/2.0 405 Method Not Allowed..Via:SIP/2.0/UDP 198.1.55.123:5060;branch=z9hG4bK00a3.b9cbedf3.0..From: <sip:dispatcher@1
98.1.55.73>;tag=e01ea3f0a697069df7513da937492475-ccc2..To: sip:4.55.23.33:5060..Call-ID: 4c219ec71b602dc9-3450@198.1.55.
123..CSeq: 14 OPTIONS..Allow: INVITE,ACK,CANCEL,BYE,REFER,SUBSCRIBE,PRACK,UPDATE..Content-Length: 0....

U 4.55.23.33:5060 -> 198.1.55.123:5060
SIP/2.0 405 Method Not Allowed..Via:SIP/2.0/UDP 198.1.55.123:5060;branch=z9hG4bK7533.9d187cb.0..From: <sip:dispatcher@19
8.1.55.73>;tag=e01ea3f0a697069df7513da937492475-9090..To: sip:4.55.23.33:5060..Call-ID: 4c219ec71b602dd0-3450@198.1.55.1
23..CSeq: 14 OPTIONS..Allow: INVITE,ACK,CANCEL,BYE,REFER,SUBSCRIBE,PRACK,UPDATE..Content-Length: 0....

U 4.55.23.33:5060 -> 198.1.55.123:5060
SIP/2.0 405 Method Not Allowed..Via:SIP/2.0/UDP 198.1.55.123:5060;branch=z9hG4bKba93.6ec09736.0..From: <sip:dispatcher@1
98.1.55.73>;tag=e01ea3f0a697069df7513da937492475-aff4..To: sip:4.55.23.33:5060..Call-ID: 4c219ec71b602dce-3450@198.1.55.
123..CSeq: 14 OPTIONS..Allow: INVITE,ACK,CANCEL,BYE,REFER,SUBSCRIBE,PRACK,UPDATE..Content-Length: 0....

DBG:dispatcher:ds_options_callback: OPTIONS-Request was finished with code 408 (to sip:4.55.23.33:5060, group 2)
Jul 31 20:07:11 13cn8 /usr/local/opensips/sbin/opensips[4537]: DBG:dispatcher:ds_set_state: no event sent
Jul 31 20:07:11 13cn8 /usr/local/opensips/sbin/opensips[4537]: DBG:tm:insert_timer_unsafe: [2]: 0x7f15275282d0 (65)
Jul 31 20:07:11 13cn8 /usr/local/opensips/sbin/opensips[4537]: DBG:tm:final_response_handler: done
Jul 31 20:07:11 13cn8 /usr/local/opensips/sbin/opensips[4537]: DBG:tm:timer_routine: timer routine:0,tl=0x7f152752bc80 next=0x7f152752d870, timeout=60
Jul 31 20:07:11 13cn8 /usr/local/opensips/sbin/opensips[4537]: DBG:tm:final_response_handler: Cancel sent out, sending 408 (0x7f152752ba30)
Jul 31 20:07:11 13cn8 /usr/local/opensips/sbin/opensips[4537]: DBG:tm:t_should_relay_response: T_code=0, new_code=408
Jul 31 20:07:11 13cn8 /usr/local/opensips/sbin/opensips[4537]: DBG:tm:t_pick_branch: picked branch 0, code 408 (prio=800)
Jul 31 20:07:11 13cn8 /usr/local/opensips/sbin/opensips[4537]: DBG:tm:local_reply: branch=0, save=0, winner=0
Jul 31 20:07:11 13cn8 /usr/local/opensips/sbin/opensips[4537]: DBG:tm:local_reply: local transaction completed
Jul 31 20:07:11 13cn8 /usr/local/opensips/sbin/opensips[4537]: DBG:tm:run_trans_callbacks: trans=0x7f152752ba30, callback type 256, id 0 entered
Jul 31 20:07:11 13cn8 /usr/local/opensips/sbin/opensips[4537]: DBG:dispatcher:ds_options_callback: OPTIONS-Request was finished with code 408 (to sip:4.55.19.33:5060, group 1)

[bogdan-iancu]

It is hard to think that the OpenSIPS mixes replies :) . I rather think the 405 is not received by OpenSIPs (or discarded as malformed?), so the OPTIONS transaction gives internal timeout (as no reply received) -> 408 .

Check the logs showing the timeout:

Jul 31 20:07:11 13cn8 /usr/local/opensips/sbin/opensips[4537]: DBG:tm:final_response_handler: Cancel sent out, sending 408 (0x7f152752ba30)

Are you sure the 405 gets to opensips - are there logs related to processing that reply ?

[bogdan-iancu]

After an offline chat with Norman, it seems to be what I suspected - the received 405 is not matched and transaction generates internal timeout. This is not a bug.