coding-marisa
commented
1 year ago Updating error description and adding up to date logs
Closed coding-marisa closed 1 year ago
coding-marisa
commented
1 year ago Updating error description and adding up to date logs
davehorton
commented
1 year ago OK, you definitely found a good bug in jambonz, so thanks for that! I have checked in a fix and this will appear in tag v0.7.7-12
However, your code is also wrong, and needs to be fixed. This return statement does not do what you intend it to do -- to return a payload to jambonz. For that you need to use the res object.
What you want to do is this:
const WebhookResponse = require('@jambonz/node-client').WebhookResponse;
router.post('/answeringMachineDetection', (req, res) => {
const { logger } = req.app.locals;
const payload = req.body;
const { type, reason } = payload;
logger.info({payload}, 'POST /menu-demo/answeringMachineDetection');
if (type === 'amd_no_speech_detected') {
const app = new WebhookResponse();
app.say({
text: 'Record your message and press pound or press star to contact the operator.',
synthesizer : {
vendor: 'Google',
language: 'en-US'
}
});
return res.status(200).json(app);
}
// otherwise, just return a 200
res.sendStatus(200);
});Note that using the @jambonz/node-client' package makes this much easier. If you are not using this in your webhook app you should be.
I will update and close this ticket once v0.7.7-12 is available. In the meantime, making the fix to your code as outlined above should resolve your problem
davehorton
commented
1 year ago images for 0.7.7-12 are now available.
It would be helpful if you could test and verify the fix in the following sequence:
Let me know if you are willing/able to do this @marisa-contract, if you are I will keep the ticket open for now until you verify the fix(es)
coding-marisa
commented
1 year ago davehorton
commented
1 year ago your webhook is still returning a 503 for some reason. Can you provide the logging from your webhook application so we can see why that is?
coding-marisa
commented
1 year ago I have included the app logs for three test calls. Test calls 1 and 2 cause no restarts and an AMD hook is present in the logging. Test call 3 has no AMD hook in the log and causes a restart. Test Call 1 - Human Greeting Test Call 2 - Voicemail with Speech Test Call 3 - Human Answers while on Mute
davehorton
commented
1 year ago something is returning a 503 to the http post request in test call 3. Can you look into that and figure out what?
If not, just do upgrade to jambonz and retest
coding-marisa
commented
1 year ago We will upgrade to the newest version now, but for one final test I ran the program with a simplified amd web hook and encountered intermittent restarts. When a call ends on a successful test, when one person hangs up the other half of the call is also terminated. When the test call fails and the pod restarts, when one half of the call hangs up the other person's call will continue until they hang up manually.
Simplified Code
router.post('/answeringMachineDetection', (req, res) => {
const { logger } = req.app.locals;
const payload = req.body;
logger.info({payload}, 'POST /menu-demo/answeringMachineDetection');
res.sendStatus(200);
});No restart, call ends for both parties at hang up. "msg":"SingleDialer:exec called party hung up"
// First line that differs between the success and failure tests
2022-11-07T16:55:47.541726437Z {"level":20,"time":1667840147541,"pid":1,"hostname":"feature-server-586dcccdfc-ht6cl","callSid":"74fd193e-73f6-406a-95ea-6d331f6a5338","parentCallSid":"cbed4f20-8dab-4b60-b625-fe3b705fd714","callId":"cdcb4483-d95f-123b-3a8b-12683a7f3961","msg":"SingleDialer:exec called party hung up"}
2022-11-07T16:55:47.566387804Z {"level":20,"time":1667840147544,"pid":1,"hostname":"feature-server-586dcccdfc-ht6cl","callId":"c6f10a62-d95f-123b-aab1-42010a800025","callSid":"cbed4f20-8dab-4b60-b625-fe3b705fd714","accountSid":"9e4ae03e-3702-495e-b34d-8107a8b19123","callingNumber":"+15419330450","calledNumber":"+16514241607","traceId":"b04da22af240344e615cc44675117fcc","url":"http://c63b-24-20-1-20.ngrok.io/call-status","absUrl":"http://c63b-24-20-1-20.ngrok.io/call-status","hdrs":{"Jambonz-Signature":"t=1667840147,v1=a177a8111aa93f53e4b70de6c1fd25f2c2ac46a1e07f16f448090a931e475d52","Content-Type":"application/json"},"msg":"send webhook"}
2022-11-07T16:55:47.566422961Z {"level":20,"time":1667840147549,"pid":1,"hostname":"feature-server-586dcccdfc-ht6cl","callId":"c6f10a62-d95f-123b-aab1-42010a800025","callSid":"cbed4f20-8dab-4b60-b625-fe3b705fd714","accountSid":"9e4ae03e-3702-495e-b34d-8107a8b19123","callingNumber":"+15419330450","calledNumber":"+16514241607","traceId":"b04da22af240344e615cc44675117fcc","msg":"Dial:_selectSingleDial called party hungup, ending dial operation"}
2022-11-07T16:55:47.566451993Z {"level":30,"time":1667840147549,"pid":1,"hostname":"feature-server-586dcccdfc-ht6cl","msg":"SessionTracker:remove callSid 74fd193e-73f6-406a-95ea-6d331f6a5338, we have 1 being tracked"}Restart occurs, both parties must hang up "msg":"web callback returned unexpected status code 503"
// First line that differs between the success and failure tests
2022-11-07T16:56:48.018945835Z {"level":30,"time":1667840208018,"pid":1,"hostname":"feature-server-586dcccdfc-ht6cl","callId":"f3554d9f-d95f-123b-aab1-42010a800025","callSid":"6c52265e-0481-4514-a339-98d3dc200bb9","accountSid":"9e4ae03e-3702-495e-b34d-8107a8b19123","callingNumber":"+15419330450","calledNumber":"+16514241607","traceId":"9c4e091d394549d063d1af8d14bc229c","baseUrl":"http://c63b-24-20-1-20.ngrok.io","url":"/menu-demo/answeringMachineDetection","msg":"web callback returned unexpected status code 503"}
2022-11-07T16:56:48.036205002Z /opt/app/lib/utils/http-requestor.js:132
2022-11-07T16:56:48.036296802Z const err = new Error();
2022-11-07T16:56:48.036307662Z ^
2022-11-07T16:56:48.036313834Z
2022-11-07T16:56:48.036320919Z Error
2022-11-07T16:56:48.036332465Z at HttpRequestor.request (/opt/app/lib/utils/http-requestor.js:132:21)
2022-11-07T16:56:48.036340943Z at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
2022-11-07T16:56:48.036347709Z at async TaskDial.performHook (/opt/app/lib/tasks/task.js:180:20) {
2022-11-07T16:56:48.036355030Z statusCode: 503
2022-11-07T16:56:48.036361312Z }
2022-11-07T16:56:48.036367882Z
2022-11-07T16:56:48.036376017Z Node.js v18.9.0After the upgrade, I will test both correct and incorrect amd web hooks code to confirm neither initiates a restart.
davehorton
commented
1 year ago you really need to figure out why your webhook is returning a 503 failure. For now, I will leave that on your side. Just do the upgrade and retest please
davehorton
commented
1 year ago @marisa-contract were you able to retest after the upgrade?
coding-marisa
commented
1 year ago After upgrading to 0.7.7-13 we are still experiencing feature server restarts when using amd web hooks. The error prior to the restart in feature-server/feature-server is now if (!this._conn) return callback(new Error('endpoint no longer active'));.
Portion of Feature Server - Feature Server log.
2022-11-21T19:19:11.018518192Z /opt/app/node_modules/drachtio-fsmrf/lib/endpoint.js:1073
2022-11-21T19:19:11.018587689Z if (!this._conn) return callback(new Error('endpoint no longer active'));
2022-11-21T19:19:11.018597022Z ^
2022-11-21T19:19:11.018602798Z
2022-11-21T19:19:11.018624706Z Error: endpoint no longer active
2022-11-21T19:19:11.018630489Z at __x (/opt/app/node_modules/drachtio-fsmrf/lib/endpoint.js:1073:40)
2022-11-21T19:19:11.018636752Z at Endpoint.api (/opt/app/node_modules/drachtio-fsmrf/lib/endpoint.js:1082:7)
2022-11-21T19:19:11.018642773Z at __x (/opt/app/node_modules/drachtio-fsmrf/lib/endpoint.js:818:12)
2022-11-21T19:19:11.018648290Z at /opt/app/node_modules/drachtio-fsmrf/lib/endpoint.js:834:7
2022-11-21T19:19:11.018653546Z at new Promise (<anonymous>)
2022-11-21T19:19:11.018659372Z at Endpoint.stopTranscription (/opt/app/node_modules/drachtio-fsmrf/lib/endpoint.js:833:12)
2022-11-21T19:19:11.018664869Z at Amd.<anonymous> (/opt/app/lib/utils/amd-utils.js:276:12)
2022-11-21T19:19:11.018670040Z at Amd.emit (node:events:513:28)
2022-11-21T19:19:11.018675340Z at Amd.emit (node:domain:489:12)
2022-11-21T19:19:11.018680420Z at Amd._onNoSpeechTimeout (/opt/app/lib/utils/amd-utils.js:115:10)Part of the problem is this
Invalid Application avmd_startWhat tag for the freeswitch image are you using?
coding-marisa
commented
1 year ago In feature-server.yaml the tag is 0.4.17 (image: drachtio/drachtio-freeswitch-mrf:0.4.17). Here is the deployment information from the cluster as well.
kubectl get deployments -o wide -n jambonz
NAME READY UP-TO-DATE AVAILABLE AGE CONTAINERS IMAGES SELECTOR
api-server 1/1 1 1 206d api-server jambonz/api-server:0.7.7-13 app=api-server
feature-server 1/1 1 1 206d drachtio,freeswitch,feature-server drachtio/drachtio-server:0.8.18,drachtio/drachtio-freeswitch-mrf:0.4.17,jambonz/feature-server:0.7.7-13 app=feature-server
sbc-call-router 1/1 1 1 206d sbc-call-router jambonz/sbc-call-router:0.7.7-13 app=sbc-call-router
sbc-inbound 1/1 1 1 206d sbc-inbound jambonz/sbc-inbound:0.7.7-13 app=sbc-inbound
sbc-outbound 1/1 1 1 206d sbc-outbound jambonz/sbc-outbound:0.7.7-13 app=sbc-outbound
webapp 1/1 1 1 206d webapp jambonz/webapp:0.7.7-13 app=webappare you still experiencing this?
coding-marisa
commented
1 year ago We are no longer experiencing this in v0.7.8. Thank you for your assistance!
Issue: Feature-server pod is restarting after amd webhook. Jambonz on GKE, v 0.7.7-9 @jambonz/node-client 0.3.29 3cx PBX & Twilio Trunks App overview: The app is set to a fixed number on a Twilio trunk. After app starts, caller inputs the extension to be forwarded to. The call is transferred to this extension using the PBX trunk (this is to allow for the outbound number to be 3-digit extensions rather than a DID). If extension answers, proceed with normal call. If voicemail answers, listen for answering machine message. If no speech is detected, use say verb to provide instructions for caller.
Currently, calls that are answered by the destination extension (a person) restart the feature-server pod at the call's termination. Calls that instead reach the destination’s voicemailbox seem to not restart the feature-server pod. Demo App Endpoint
Logs
``` feature-server feature-server Old and Restarted Pods ```
``` 2022-11-05T04:59:25.123167826Z {"level":20,"time":1667624365122,"pid":1,"hostname":"feature-server-586dcccdfc-njs7s","msg":"installing srf locals"} 2022-11-05T04:59:26.161637352Z {"level":30,"time":1667624365125,"pid":1,"hostname":"feature-server-586dcccdfc-njs7s","sbcs":["sbc-sip.jambonz:5060"],"msg":"SBC inventory"} 2022-11-05T04:59:26.161675547Z {"level":30,"time":1667624365163,"pid":1,"hostname":"feature-server-586dcccdfc-njs7s","msg":"sending stats to telegraf.monitoring"} 2022-11-05T04:59:26.161685072Z {"level":30,"time":1667624365164,"pid":1,"hostname":"feature-server-586dcccdfc-njs7s","fsInventory":[{"address":"127.0.0.1","port":"8021","secret":"JambonzR0ck$"}],"msg":"freeswitch inventory"} 2022-11-05T04:59:26.161692570Z {"level":30,"time":1667624366160,"pid":1,"hostname":"feature-server-586dcccdfc-njs7s","msg":"listening for HTTP requests on port 3000, serviceUrl is http://10.0.2.39:3000"} 2022-11-05T04:59:26.176497904Z {"level":30,"time":1667624366173,"pid":1,"hostname":"feature-server-586dcccdfc-njs7s","msg":"disabling OPTIONS pings since we are running as a kubernetes service"} 2022-11-05T04:59:26.201375009Z {"level":20,"time":1667624366195,"pid":1,"hostname":"feature-server-586dcccdfc-njs7s","args":[],"msg":"redis event connect"} 2022-11-05T04:59:26.220670881Z {"level":30,"time":1667624366220,"pid":1,"hostname":"feature-server-586dcccdfc-njs7s","msg":"connected to drachtio listening on udp/127.0.0.1:5060,udp/10.0.2.39:5060, local sip address is 10.0.2.39:5060"} 2022-11-05T04:59:26.227482981Z {"level":30,"time":1667624366223,"pid":1,"hostname":"feature-server-586dcccdfc-njs7s","msg":"connected to freeswitch at 127.0.0.1"} 2022-11-05T04:59:26.227537497Z {"level":20,"time":1667624366227,"pid":1,"hostname":"feature-server-586dcccdfc-njs7s","args":[],"msg":"redis event ready"} 2022-11-05T05:01:53.473197866Z {"level":30,"time":1667624513472,"pid":1,"hostname":"feature-server-586dcccdfc-njs7s","callId":"ce401e37-d769-123b-aab1-42010a800025","msg":"new incoming call"} 2022-11-05T05:01:53.482515819Z {"level":20,"time":1667624513473,"pid":1,"hostname":"feature-server-586dcccdfc-njs7s","msg":"got application from X-Application-Sid header: 5105a417-b270-4665-896e-7a087bebb844"} 2022-11-05T05:01:53.505039597Z {"level":20,"time":1667624513504,"pid":1,"hostname":"feature-server-586dcccdfc-njs7s","accountInfo":{"account_sid":"9e4ae03e-3702-495e-b34d-8107a8b19123","name":"TestAccount","sip_realm":null,"service_provider_sid":"2708b1b3-2736-40ea-b502-c53d8396247f","registration_hook_sid":null,"queue_event_hook_sid":null,"device_calling_application_sid":null,"is_active":1,"created_at":"2022-11-03T22:47:18.000Z","plan_type":"trial","stripe_customer_id":null,"webhook_secret":"wh_secret_xzBzVCH8Fdx5UjKogxpMHH","disable_cdrs":0,"trial_end_date":null,"deactivated_reason":null,"device_to_call_ratio":5,"subspace_client_id":null,"subspace_client_secret":null,"subspace_sip_teleport_id":null,"subspace_sip_teleport_destinations":null,"siprec_hook_sid":null},"msg":"retrieved account info for 9e4ae03e-3702-495e-b34d-8107a8b19123"} 2022-11-05T05:01:53.521778528Z {"level":30,"time":1667624513521,"pid":1,"hostname":"feature-server-586dcccdfc-njs7s","callId":"ce401e37-d769-123b-aab1-42010a800025","callSid":"831c0f64-d9cd-41a5-8232-35efee4963ff","accountSid":"9e4ae03e-3702-495e-b34d-8107a8b19123","callingNumber":"+15419330450","calledNumber":"+16514241607","traceId":"3f4626cb343615c5dfa611a928d75986","app":{"application_sid":"5105a417-b270-4665-896e-7a087bebb844","name":"MenuDemo","service_provider_sid":null,"account_sid":"9e4ae03e-3702-495e-b34d-8107a8b19123","call_hook_sid":"27399d5e-c798-45cb-b311-4e9665ef5472","call_status_hook_sid":"f6a06a72-f9aa-457a-9602-6e4fd0a4b886","messaging_hook_sid":"7632e5b4-0414-4b83-90c2-cd5a2ee74c67","speech_synthesis_vendor":"google","speech_synthesis_language":"en-US","speech_synthesis_voice":"en-US-Standard-C","speech_recognizer_vendor":"google","speech_recognizer_language":"en-US","created_at":"2022-11-03T23:29:10.000Z"},"msg":"retrieved application for incoming call to 16514241607"} 2022-11-05T05:01:53.537024515Z {"level":20,"time":1667624513525,"pid":1,"hostname":"feature-server-586dcccdfc-njs7s","callId":"ce401e37-d769-123b-aab1-42010a800025","callSid":"831c0f64-d9cd-41a5-8232-35efee4963ff","accountSid":"9e4ae03e-3702-495e-b34d-8107a8b19123","callingNumber":"+15419330450","calledNumber":"+16514241607","traceId":"3f4626cb343615c5dfa611a928d75986","params":{"sip":{"headers":{"via":"SIP/2.0/UDP 34.70.230.94;rport=5060;branch=z9hG4bK1jr1myDXUUmQK;received=10.128.0.37","max-forwards":"70","from":"This is a demo app. Please input or say the extension of the employee you are trying to reach.\nThis is a demo app. Please input or say the extension of the employee you are trying to reach.\n