Instant messaging Asterisk

FatimaJaffal · October 27, 2022, 10:59pm

Hello,

I’m trying to use IM with Asterisk, I added the following to my sip.conf file:

accept_outofcall_message=yes
auth_message_requests=yes
outofcall_message_context=test

and in extensions.conf

[test]
exten =>  _[0-9a-z].,1,NoOp()
 same => n,NoOp(test message!!!)
 same => n,Hangup()

I see that Asterisk receives the message, but it doesn’t execute the context for some reason.

Here’s sip logs:

<--- SIP read from UDP:172.31.27.155:51921 --->
MESSAGE sip:1@172.31.27.155 SIP/2.0
Via: SIP/2.0/UDP 172.31.27.155:51921;rport;branch=z9hG4bK5jyU9j1H2D5cm
Max-Forwards: 70
From: <sip:NmVhNTE2MDktNGFmMC00MjdiLWExNjAtZDdlOWQ1YmY2YTQxOjg3NjE3MDRh@172.31.27.155:51921;transport=udp>;tag=41r6XS0g4F69K
To: <sip:1@172.31.27.155>
Call-ID: mbIZLlNQa2xnwxel1gOM1aN
CSeq: 968975057 MESSAGE
User-Agent: Janus WebRTC Server SIP Plugin 0.0.8
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, UPDATE, REFER, MESSAGE, INFO, NOTIFY
Supported: replaces
Content-Type: text/plain
Content-Length: 7

test!!!
<------------->
--- (12 headers 1 lines) ---
Sending to 172.31.27.155:51921 (no NAT)
Receiving message!
Found peer 'NmVhNTE2MDktNGFmMC00MjdiLWExNjAtZDdlOWQ1YmY2YTQxOjg3NjE3MDRh' for 'NmVhNTE2MDktNGFmMC00MjdiLWExNjAtZDdlOWQ1YmY2YTQxOjg3NjE3MDRh' from 172.31.27.155:51921
Looking for 1 in test (domain 172.31.27.155)

<--- Transmitting (no NAT) to 172.31.27.155:51921 --->
SIP/2.0 202 Accepted
Via: SIP/2.0/UDP 172.31.27.155:51921;branch=z9hG4bK5jyU9j1H2D5cm;received=172.31.27.155;rport=51921
From: <sip:NmVhNTE2MDktNGFmMC00MjdiLWExNjAtZDdlOWQ1YmY2YTQxOjg3NjE3MDRh@172.31.27.155:51921;transport=udp>;tag=41r6XS0g4F69K
To: <sip:1@172.31.27.155>;tag=as0e3e4c99
Call-ID: mbIZLlNQa2xnwxel1gOM1aN
CSeq: 968975057 MESSAGE
Server: Asterisk PBX 18.13.0
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0

david551 · October 27, 2022, 11:02pm

Your pattern requires at least two characters.

FatimaJaffal · October 27, 2022, 11:12pm

I changed it to _X., but still the same issue.

david551 · October 27, 2022, 11:25pm

That’s because it still requires two characters.

As the first part of your pattern matches all the characters that cause problems with _. you could just use that. However, if h, i, e, t, etc. are important, you will need two extensions, one to match safe one character patterns and one to match two or more character patterns.

You could use ! instead of ., to get a one character match on what precedes it, with the same caveats about special extensions. Note that ! forces early matches, but that shouldn’t matter for messages.

FatimaJaffal · October 27, 2022, 11:30pm

Hi, thanks for your help.

I tried to do the following:

[test]
exten =>  12,1,NoOp()
 same => n,NoOp(test message!!!)
 same => n,Hangup()

but still the same issue.

Here’s sip logs:

<--- SIP read from UDP:172.31.27.155:54610 --->
MESSAGE sip:12@172.31.27.155 SIP/2.0
Via: SIP/2.0/UDP 172.31.27.155:54610;rport;branch=z9hG4bK9ygQ566HNm3Kj
Max-Forwards: 70
From: <sip:ZDUyMDdhMWMtYjZjNy00ZGQxLTk2ZGItNjc3MTRkMzhiNGE1OmIwOWY5NDAy@172.31.27.155:54610;transport=udp>;tag=8Hvp4a1a50Uve
To: <sip:12@172.31.27.155>
Call-ID: 5XQrMfWiYq7z9KMVHKLzNAh
CSeq: 968975522 MESSAGE
User-Agent: Janus WebRTC Server SIP Plugin 0.0.8
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, UPDATE, REFER, MESSAGE, INFO, NOTIFY
Supported: replaces
Content-Type: text/plain
Content-Length: 7

test!!!
<------------->
--- (12 headers 1 lines) ---
Sending to 172.31.27.155:54610 (no NAT)
Receiving message!
Found peer 'ZDUyMDdhMWMtYjZjNy00ZGQxLTk2ZGItNjc3MTRkMzhiNGE1OmIwOWY5NDAy' for 'ZDUyMDdhMWMtYjZjNy00ZGQxLTk2ZGItNjc3MTRkMzhiNGE1OmIwOWY5NDAy' from 172.31.27.155:54610
Looking for 12 in test (domain 172.31.27.155)

<--- Transmitting (no NAT) to 172.31.27.155:54610 --->
SIP/2.0 202 Accepted
Via: SIP/2.0/UDP 172.31.27.155:54610;branch=z9hG4bK9ygQ566HNm3Kj;received=172.31.27.155;rport=54610
From: <sip:ZDUyMDdhMWMtYjZjNy00ZGQxLTk2ZGItNjc3MTRkMzhiNGE1OmIwOWY5NDAy@172.31.27.155:54610;transport=udp>;tag=8Hvp4a1a50Uve
To: <sip:12@172.31.27.155>;tag=as6550df9a
Call-ID: 5XQrMfWiYq7z9KMVHKLzNAh
CSeq: 968975522 MESSAGE
Server: Asterisk PBX 18.13.0
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0

``

Vinayak · October 28, 2022, 2:50am

Can u try this

exten => _X.,1,NoOp(Body ${MESSAGE(body)})

david551 · October 28, 2022, 10:15am

Do you actually have the verbosity high enough (at least 3) to show the Noop?

FatimaJaffal · October 28, 2022, 11:41am

I tried it, same issue

FatimaJaffal · October 28, 2022, 11:42am

Yes, I use sudo asterisk -rvvvvv

david551 · October 28, 2022, 12:02pm

Try setting debug level to at least 5 on main/message.c, to see if it reaches this line:

github.com

asterisk/asterisk/blob/master/main/message.c#L936


      
          
          
	ast_rwlock_rdlock(&msg_handlers_lock);
          	for (i = 0; i < AST_VECTOR_SIZE(&msg_handlers); i++) {
          		const struct ast_msg_handler *handler = AST_VECTOR_GET(&msg_handlers, i);
          
          
		if (!handler->has_destination(msg)) {
          			ast_debug(5, "Handler %s doesn't want message, moving on\n", handler->name);
          			continue;
          		}
          
          
		ast_debug(5, "Dispatching message to %s handler\n", handler->name);
          		res &= handler->handle_msg(msg);
          	}
          	ast_rwlock_unlock(&msg_handlers_lock);
          
          
	if (res != 0) {
          		ast_log(LOG_WARNING, "No handler processed message from %s to %s\n",
          			S_OR(msg->from, "<unknown>"), S_OR(msg->to, "<unknown>"));
          	}
          
          
	ao2_ref(msg, -1);

FatimaJaffal · October 28, 2022, 12:31pm

It doesn’t seem to reach it

[Oct 28 12:21:00] DEBUG[1154766]: chan_sip.c:9107 __sip_alloc: Allocating new SIP dialog for eiOY8A8uhGmkC8Y5li5RTs4 - MESSAGE (No RTP)
[Oct 28 12:21:00] DEBUG[1154766]: chan_sip.c:29201 handle_incoming: **** Received MESSAGE (11) - Command in SIP MESSAGE
Receiving message!
[Oct 28 12:21:00] DEBUG[1154766]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '172.31.27.155:36326' into...
[Oct 28 12:21:00] DEBUG[1154766]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '172.31.27.155' and port ''.
Found peer 'MzliZTUxNmQtYjM3My00YjE5LThkZjMtZmJhMDUyYTIxZDhlOmI1ZjUzZWVl' for 'MzliZTUxNmQtYjM3My00YjE5LThkZjMtZmJhMDUyYTIxZDhlOmI1ZjUzZWVl' from 172.31.27.155:36326
[Oct 28 12:21:00] DEBUG[1154766]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '172.31.27.155' into...
[Oct 28 12:21:00] DEBUG[1154766]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '172.31.27.155' and port ''.
[Oct 28 12:21:00] DEBUG[1154766]: netsock2.c:170 ast_sockaddr_split_hostport: Splitting '172.31.27.155:36326' into...
[Oct 28 12:21:00] DEBUG[1154766]: netsock2.c:224 ast_sockaddr_split_hostport: ...host '172.31.27.155' and port ''.
Looking for 12 in test (domain 172.31.27.155)
[Oct 28 12:21:00] DEBUG[1154766]: message.c:960 ast_msg_has_destination: Seeing if dialplan can handle message
[Oct 28 12:21:00] DEBUG[1154766]: message.c:962 ast_msg_has_destination: dialplan can handle message
<--- Transmitting (no NAT) to 172.31.27.155:36326 --->
SIP/2.0 202 Accepted
Via: SIP/2.0/UDP 172.31.27.155:36326;branch=z9hG4bKDg27p1peByX3g;received=172.31.27.155;rport=36326
From: <sip:MzliZTUxNmQtYjM3My00YjE5LThkZjMtZmJhMDUyYTIxZDhlOmI1ZjUzZWVl@172.31.27.155:36326;transport=udp>;tag=c7BH022SmN0ac
To: <sip:12@172.31.27.155>;tag=as2f4e8f21
Call-ID: eiOY8A8uhGmkC8Y5li5RTs4
CSeq: 968987117 MESSAGE
Server: Asterisk PBX 18.13.0
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0

david551 · October 28, 2022, 12:52pm

Do you have a problem with task processor queue sizes, as you have the debugs from before the request is put on the queue, but not after it is taken off.

FatimaJaffal · October 28, 2022, 1:10pm

In that case I should see warnings in the console, no?

david551 · October 28, 2022, 2:21pm

If you you have actually gone over a warning limit, you should see messages. If the queue is growing because of some sort of deadlock, but hasn’t tripped the limit, you will only get the warning when you reach the threshold.

I’m basically going on the fact that your debug shows debug lines from just before the message gets added to the queue and not from when it should have come off the queue.

It’s showing this line:

github.com

asterisk/asterisk/blob/master/main/message.c#L962


      
          {
          	int i;
          	int result = 0;
          
          
	ast_rwlock_rdlock(&msg_handlers_lock);
          	for (i = 0; i < AST_VECTOR_SIZE(&msg_handlers); i++) {
          		const struct ast_msg_handler *handler = AST_VECTOR_GET(&msg_handlers, i);
          
          
		ast_debug(5, "Seeing if %s can handle message\n", handler->name);
          		if (handler->has_destination(msg)) {
          			ast_debug(5, "%s can handle message\n", handler->name);
          			result = 1;
          			break;
          		}
          	}
          	ast_rwlock_unlock(&msg_handlers_lock);
          
          
	return result;
          }
          
          
int ast_msg_queue(struct ast_msg *msg)

but not this one:

github.com

asterisk/asterisk/blob/master/main/message.c#L936


      
          
          
	ast_rwlock_rdlock(&msg_handlers_lock);
          	for (i = 0; i < AST_VECTOR_SIZE(&msg_handlers); i++) {
          		const struct ast_msg_handler *handler = AST_VECTOR_GET(&msg_handlers, i);
          
          
		if (!handler->has_destination(msg)) {
          			ast_debug(5, "Handler %s doesn't want message, moving on\n", handler->name);
          			continue;
          		}
          
          
		ast_debug(5, "Dispatching message to %s handler\n", handler->name);
          		res &= handler->handle_msg(msg);
          	}
          	ast_rwlock_unlock(&msg_handlers_lock);
          
          
	if (res != 0) {
          		ast_log(LOG_WARNING, "No handler processed message from %s to %s\n",
          			S_OR(msg->from, "<unknown>"), S_OR(msg->to, "<unknown>"));
          	}
          
          
	ao2_ref(msg, -1);

or the one four lines before it.

Looking at where the first message is produced, it is in a function only called from:

github.com

asterisk/asterisk/blob/master/res/res_pjsip_messaging.c#L1453


      
          		return PJ_TRUE;
          	}
          
          
	code = rx_data_to_ast_msg(rdata, msg);
          	if (code != PJSIP_SC_OK) {
          		send_response(rdata, code, NULL, NULL);
          		ast_msg_destroy(msg);
          		return PJ_TRUE;
          	}
          
          
	if (!ast_msg_has_destination(msg)) {
          		ast_debug(1, "MESSAGE request received, but no handler wanted it\n");
          		send_response(rdata, PJSIP_SC_NOT_FOUND, NULL, NULL);
          		ast_msg_destroy(msg);
          		return PJ_TRUE;
          	}
          
          
	/* Send it to the messaging core.
          	 *
          	 * If we are unable to send a response, the most likely reason is that we
          	 * are handling a retransmission of an incoming MESSAGE and were unable to

or from a similar place in the deprecated chan_sip driver.

We know that the 202 response is being sent, a few lines further down, and the only thing that would then stop the message being queued is if the 202 wasn’t sent, but your logging indicates that it was.

chan_sip actually queues the message before sending the 202, so is even more closely tied into the logged line.

I can therefore only really assume that something is going wrong with the read-out of the queue, especially given enough people successfully handle incoming messages that the code has to be basically correct.

FatimaJaffal · October 28, 2022, 2:44pm

I can therefore only really assume that something is going wrong with the read-out of the queue, especially given enough people successfully handle incoming messages that the code has to be basically correct.

Any idea how to debug this? I don’t think it’s a code issue, it used to work before, but for some reason it doesn’t work anymore.

system · November 27, 2022, 2:45pm

This topic was automatically closed 30 days after the last reply. New replies are no longer allowed.

Topic		Replies	Views
Asterisk Instant Messaging Asterisk Support	0	990	January 29, 2015
Asterisk ignores 407 authentication request for MessageSend Asterisk SIP	6	1986	August 22, 2019
Cant receive text message with SIP Asterisk SIP	2	974	May 11, 2022
Add messaging support Asterisk Support	18	8654	May 2, 2016
Instant message for PJSIP endpoints Asterisk SIP	6	4398	March 10, 2020

Instant messaging Asterisk

Related topics