SMS webhook questions/quirks/bugs, messages replayed?

[SterlingPkg (Richard Barr)]

I’ve rolled out a preliminary SMS webhook implementation to push incoming SMS messages to a Microsoft Teams channel (based on Profile - lgaetz - FreePBX Community Forums sms2twitter.php albeit skipping IFTTT and working directly with Microsoft webhooks).

This morning however, I had some unexpected functionality, where it replayed a sizable chunk of messages from three days earlier upon receipt of a new message. I’m not sure if it’s a bug in the webhook/message queue code, or I’m fundamentally misunderstanding something about how the call works.

I see that sms webhook logs the return value from the url it calls. I had initially assumed that webhook calls happened as the message was processed, and that failures were logged and nothing further. But perhaps does it requeue/not remove them from a queue?

In the full log, the relevant log entries appear to be

[2022-04-11 10:01:53] VERBOSE[2885][C-0000019d] pbx.c: Executing [didredacted@sms-incoming:1] NoOp("Message/ast_msg_queue", "SMS came in with DID: didredacted") in new stack
[2022-04-11 10:01:53] VERBOSE[2885][C-0000019d] pbx.c: Executing [didredacted@sms-incoming:2] Goto("Message/ast_msg_queue", "s,1") in new stack
[2022-04-11 10:01:53] VERBOSE[2885][C-0000019d] pbx_builtins.c: Goto (sms-incoming,s,1)
[2022-04-11 10:01:53] VERBOSE[2885][C-0000019d] pbx.c: Executing [s@sms-incoming:1] AGI("Message/ast_msg_queue", "agi://127.0.0.1/sipstation_sms.php, RECEIVE") in new stack
[2022-04-11 10:02:58] VERBOSE[2885][C-0000019d] res_agi.c: agi://127.0.0.1/sipstation_sms.php, RECEIVE: SMS RESULT: SUCCESS
[2022-04-11 10:02:59] VERBOSE[2885][C-0000019d] res_agi.c: <Message/ast_msg_queue>AGI Script agi://127.0.0.1/sipstation_sms.php completed, returning 0
[2022-04-11 10:02:59] VERBOSE[2885][C-0000019d] pbx.c: Executing [s@sms-incoming:2] Hangup("Message/ast_msg_queue", "") in new stack
[2022-04-11 10:02:59] VERBOSE[2885][C-0000019d] pbx.c: Spawn extension (sms-incoming, s, 2) exited non-zero on 'Message/ast_msg_queue'

In the sms_webhook.log, there are 22x of these three lines back to back, right after the one actual new message was received.

[2022-04-11 10:01:58] [sms_web_hook.DEBUG]: WebHook: HTTP Post Request URL="https:\/\/domainnameredacted.com\/custom\/sms2teams.php" [] []
[2022-04-11 10:01:58] [sms_web_hook.DEBUG]: WebHook: HTTP Post Data={"status":true,"message":"Data sent to web hook","event":"Event on receiving message"} [] []
[2022-04-11 10:01:58] [sms_web_hook.DEBUG]: WebHook: HTTP Post Received Response=200 [] []

The only other thing to note is, I noticed that the time field in all the messages is nonsense, always set to epoch

Array
(
    [to] => didredacted
    [from] => phonenumredacted
    [adaptor] => Sipstation
    [time] => Wed,_31_Dec_1969_18:00:00_-0600
    [message] => Test
    [eventDirection] => in
)

[jfinstrom (James Finstrom)]

It looks like the adapter signature defaults time to null. They then strtotime null and get epoch.

public function sendMessage($to,$from,$cnam,$message,$time=null,$adaptor=null,$emid=null) 

So if the child adapter is not setting those items

parent::sendMessage('4805551212', '6025551212', 'ACME', "Catch the roadrunner"); 

Is a perfectly valid call and will result in epoch on the webhook.

There should probably be a check for this and set that to null if it is null.

Note the code for this is on your system you can grep like I did but it isn’t in any public repo so you can’t submit a patch. The fix has to be done internally.

I would file two bug tickets:

1. Improvement SMS: Data not validated for not-null in the send webhook, validate or send null
2. Improvement Sipstation(I assume): when sending/receiving a message make sure date is not-null