Hi All,
We have an issue when calling a LUA script with menu options from an H264 video enabled device the call drops part way into the call while navigating a menu due to '500 Server Internal Error'.
Trying to establish if this is a problem our end or a bug, has anyone else experienced this issue before?
Logs from an example below, our IP address is masked as x.x.x.x
nua.c:633 nua_invite() nua: nua_invite: entering
nua_stack.c:529 nua_signal() nua(0x7f25b00e8e10): sent signal r_invite
nua_stack.c:569 nua_stack_signal() nua(0x7f25b00e8e10): recv signal r_invite
nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:403 soa_set_params() soa_set_params(static::0x7f25b00f2ce0, ...) called
soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x7f25b00f2ce0) called
nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip
tport.c:4588 tport_by_name() tport(0x7f25b0005100): found 0x7f25b0147320 by name tls/x.x.x.x:7859
tport.c:3257 tport_tsend() tport_tsend(0x7f25b0147320) tpn = tls/x.x.x.x:7859
tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7f25b00e40c0 0x7f25b001fe60 755 (755)
EXECUTE sofia/internal/2001@domain sleep(2000)
tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7f25b00e40c0 0x7f25b01ca460 9 (9)
tport.c:3594 tport_vsend() tport_vsend(0x7f25b0147320): 764 bytes of 764 to tls/x.x.x.x:7859
tport.c:3492 tport_send_msg() tport_vsend returned 764
tport.c:2296 tport_set_secondary_timer() tport(0x7f25b0147320): reset timer
nta.c:8304 outgoing_send() nta: sent INVITE (121693762) to tls/x.x.x.x:7859
tport.c:4160 tport_pend() tport_pend(0x7f25b0147320): pending 0x7f25b013b770 for tls/x.x.x.x:7859 (already 0)
nta.c:1350 set_timeout() nta: timer set to 32000 ms
nua_session.c:4145 signal_call_state_change() nua(0x7f25b00e8e10): ready call updated: calling
nua_stack.c:269 nua_stack_event() nua(0x7f25b00e8e10): event i_state INVITE sent
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2018-04-18 14:54:13.139241 [DEBUG] sofia.c:7084 Channel sofia/internal/2001@domain entering state [calling][0]
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
tport.c:2773 tport_wakeup() tport_wakeup(0x7f25b0147320): events IN
tport.c:2864 tport_recv_event() tport_recv_event(0x7f25b0147320)
tport_type_tls.c:434 tport_tls_recv() tport_tls_recv(0x7f25b0147320): tls_read() returned 473
tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x7f25b0147320) msg 0x7f25b00d65f0 from (tls/x.x.x.x:7859) has 473 bytes, veclen = 1
tport.c:3023 tport_deliver() tport_deliver(0x7f25b0147320): msg 0x7f25b00d65f0 (473 bytes) from tls/x.x.x.x:7859/sips next=(nil)
nta.c:3299 agent_recv_response() nta: received 500 Server Internal Error for INVITE (121693762)
nta.c:3366 agent_recv_response() nta: 500 Server Internal Error is going to a transaction
nta.c:9564 outgoing_estimate_delay() nta_outgoing: RTT is 78.612 ms
tport.c:4222 tport_release() tport_release(0x7f25b0147320): 0x7f25b013b770 by 0x7f25b01d3eb0 with 0x7f25b00d65f0
tport.c:4588 tport_by_name() tport(0x7f25b0005100): found 0x7f25b0147320 by name tls/x.x.x.x:7859
tport.c:3257 tport_tsend() tport_tsend(0x7f25b0147320) tpn = tls/x.x.x.x:7859
tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7f25b00e40c0 0x7f25b011b590 403 (403)
tport.c:3594 tport_vsend() tport_vsend(0x7f25b0147320): 403 bytes of 403 to tls/x.x.x.x:7859
tport.c:3492 tport_send_msg() tport_vsend returned 403
tport.c:2296 tport_set_secondary_timer() tport(0x7f25b0147320): reset timer
nta.c:8304 outgoing_send() nta: sent ACK (121693762) to tls/x.x.x.x:7859
nta.c:8722 outgoing_free() nta: outgoing_free(0x7f25b0146630)
nua_stack.c:271 nua_stack_event() nua(0x7f25b00e8e10): event r_invite 500 Server Internal Error
nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:1784 soa_terminate() soa_terminate(static::0x7f25b00f2ce0) called
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x7f25b00f2ce0) called
nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip
tport.c:4588 tport_by_name() tport(0x7f25b0005100): found 0x7f25b0147320 by name tls/x.x.x.x:7859
tport.c:3257 tport_tsend() tport_tsend(0x7f25b0147320) tpn = tls/x.x.x.x:7859
tport_type_tls.c:534 tport_tls_send() tport_tls_writevec: vec 0x7f25b00e40c0 0x7f25b011b590 625 (625)
tport.c:3594 tport_vsend() tport_vsend(0x7f25b0147320): 625 bytes of 625 to tls/x.x.x.x:7859
tport.c:3492 tport_send_msg() tport_vsend returned 625
tport.c:2296 tport_set_secondary_timer() tport(0x7f25b0147320): reset timer
nta.c:8304 outgoing_send() nta: sent BYE (121693763) to tls/x.x.x.x:7859
tport.c:4160 tport_pend() tport_pend(0x7f25b0147320): pending 0x7f25b01128c0 for tls/x.x.x.x:7859 (already 0)
nua_session.c:4139 signal_call_state_change() nua(0x7f25b00e8e10): call state changed: ready -> terminating
nua_stack.c:271 nua_stack_event() nua(0x7f25b00e8e10): event i_state 500 Server Internal Error
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
tport.c:2296 tport_set_secondary_timer() tport(0x7f25b0147320): reset timer
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2018-04-18 14:54:13.239253 [DEBUG] sofia.c:7084 Channel sofia/internal/2001@domain entering state [terminating][500]
2018-04-18 14:54:13.239253 [NOTICE] sofia.c:8273 Hangup sofia/internal/2001@domain [CS_EXECUTE] [NORMAL_TEMPORARY_FAILURE]
nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
nua_stack.c:569 nua_stack_signal() nua(0x7f25b00e8e10): recv signal r_destroy
nua_dialog.c:397 nua_dialog_usage_remove_at() nua(0x7f25b00e8e10): removing session usage
nua_stack.c:529 nua_signal() nua(0x7f25b00e8e10): sent signal r_destroy
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua_session.c:4139 signal_call_state_change() nua(0x7f25b00e8e10): call state changed: terminating -> terminated
nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
nua_stack.c:269 nua_stack_event() nua(0x7f25b00e8e10): event i_state Terminated
nua_stack.c:269 nua_stack_event() nua(0x7f25b00e8e10): event i_terminated Terminated
soa.c:356 soa_destroy() soa_destroy(static::0x7f25b00f2ce0) called
nta.c:4470 nta_leg_destroy() nta_leg_destroy(0x7f25b013afd0)
2018-04-18 14:54:13.239253 [DEBUG] switch_core_session.c:2815 sofia/internal/2001@domain skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2018-04-18 14:54:13.239253 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x7f256404f450 released.
2018-04-18 14:54:13.239253 [DEBUG] switch_cpp.cpp:1112 sofia/internal/2001@domain destroy/unlink session from object
2018-04-18 14:54:13.239253 [DEBUG] switch_core_media.c:5970 sofia/internal/2001@domain Video thread ended
Thanks,
Shaun
______________________________________________________________________This message has been checked for all known viruses by MessageLabs Virus Scanning Service._______________________________________________________________________________________________________________________________________________Professional FreeSWITCH Consulting Services:consulting@freeswitch.orghttp://www.freeswitchsolutions.comOfficial FreeSWITCH Siteshttp://www.freeswitch.orghttp://confluence.freeswitch.orghttp://www.cluecon.comFreeSWITCH-users mailing listFreeSWITCH-users@lists.freeswitch.orghttp://lists.freeswitch.org/mailman/listinfo/freeswitch-usersUNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-usershttp://www.freeswitch.org