Application Record() unexpected behavior

Asterisk Asterisk Support
1

Dear all,

I am using application Record() on a solution I have build and I observed a really weird behavior that is not aligned with the specifications of this function. Please have a look first at the logs below:

[Oct 15 11:43:06] VERBOSE[][] pbx.c: Executing [s@recording:11] Record("PJSIP/opensips-00000166", "/myPath/myFile.wav,3,180,ko") in new stack
[Oct 15 11:43:06] VERBOSE[][] file.c: <PJSIP/opensips-00000166> Playing 'beep.slin' (language 'en')
[Oct 15 11:46:06] VERBOSE[][] pbx.c: Executing [h@recording:1] GotoIf("PJSIP/opensips-00000166", "0?check_fax") in new stack
[Oct 15 11:46:06] VERBOSE[][] pbx.c: Executing [h@recording:2] GotoIf("PJSIP/opensips-00000166", "1?check_duration:abort_deposit") in new stack
[Oct 15 11:46:06] VERBOSE[][] pbx.c: Executing [h@recording:3] Set("PJSIP/opensips-00000166", "vmail_duration=0.000000") in new stack

Application Record() is called, in order to save wav to a specific file, using a silence of 3sec and maxduration of 180sec=3min. Additionally, options ko are used, in order to keep the recorded file upon hangup and exit when also ‘0’ is pressed.

According to the user and according to the logs from core network, this call was immediately disconnected when the ‘beep’ sound of Record() was heard.
However, at the logs we can observe that the Record() was not interrupted at hangup. However, recording continues and is stopped after 3 minutes (probably when maxduration was reached). Moreover, call flow execution goes to h extension, as if hangup was performed. Furthermore, I use a ‘sox’ command, in order to estimate the length of the recorded wav file and it takes a value of 0sec, as if nothing was recorded.

According to manual and according to all tests I have done so far, this behavior is unexpected.
In case hangup is detected, Record() should stop, STATUS turns to HANGUP and call flow execution goes to h extension.
In case no hangup is detected, Recording should stop if 3sec silence is detected, or if maxduration of 180sec is reached. At the latter case the corresponding recorded wav should not be of zero length, since recording was running for 180sec.

This issue is found only once. My major concern is that it could be an error that will be reproduced often, causing unexpected call flow execution.
The expertise of the community is really useful at this case. Are similar issues with Record() already reported? Do you think that this error could be easily reproduced? How could you justify such a behavior?

Thank you in advance for your time and interest.
Best Regards.

2

Record must have stopped for h t be executed!

3

Hi all,

I managed to reproduce the issue at test environment, so I have also the debug logs.
Please check below.
Record() is started at 18:19:13
BYE seems to be received at 18:19:13
Record() stops at 18:22:13, after 3 minutes (timeout configuration) with HANGUP status

According to documentation Record() should have been interrupted and h extension should be triggered.

[Oct 20 18:19:13] DEBUG[2491029][C-00000006] pbx.c: Launching 'Record'
[Oct 20 18:19:13] VERBOSE[2491029][C-00000006] pbx.c: Executing [s@recording:11] Record("PJSIP/opensips-00000005", "Voicemail.wav,3,180,ko") in new stack
[Oct 20 18:19:13] DEBUG[2491029][C-00000006] channel.c: Channel PJSIP/opensips-00000005 setting write format path: slin -> alaw
[Oct 20 18:19:13] DEBUG[2491029][C-00000006] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Oct 20 18:19:13] VERBOSE[2491029][C-00000006] file.c: <PJSIP/opensips-00000005> Playing 'beep.slin' (language 'en')
[Oct 20 18:19:13] DEBUG[2491029][C-00000006] channel.c: Scheduling timer at (364 requested / 364 actual) timer ticks per second
[Oct 20 18:19:13] DEBUG[2382333] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7f538000ada8 for Request msg BYE/cseq=2 (rdata0x7f541c003e78)
[Oct 20 18:19:13] DEBUG[2382333] res_pjsip/pjsip_distributor.c: Found serializer pjsip/distributor-00000024 associated with dialog dlg0x7f538000ada8
[Oct 20 18:19:13] DEBUG[2489556] res_pjsip_session.c:  PJSIP/opensips-00000005 TSX State: Completed  Inv State: CONFIRMED
[Oct 20 18:19:13] DEBUG[2489556] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Oct 20 18:19:13] DEBUG[2489556] res_pjsip_session.c: The state change pertains to the endpoint 'opensips(PJSIP/opensips-00000005)'
[Oct 20 18:19:13] DEBUG[2489556] res_pjsip_session.c: The inv session does NOT have an invite_tsx
[Oct 20 18:19:13] DEBUG[2489556] res_pjsip_session.c: The UAS BYE transaction involved in this state change is 0x7f538000c638
[Oct 20 18:19:13] DEBUG[2489556] res_pjsip_session.c: The current transaction state is Completed
[Oct 20 18:19:13] DEBUG[2489556] res_pjsip_session.c: The transaction state change event is TX_MSG
[Oct 20 18:19:13] DEBUG[2489556] res_pjsip_session.c: The current inv state is CONFIRMED
[Oct 20 18:19:13] DEBUG[2489556] res_pjsip_session.c:  Nothing delayed
[Oct 20 18:19:13] DEBUG[2489556] res_pjsip_session.c:  PJSIP/opensips-00000005 TSX State: Completed  Inv State: CONFIRMED
[Oct 20 18:19:13] DEBUG[2489556] res_pjsip_session.c:  Topology: Pending: (null topology)  Active:  <0:audio-0:audio:sendrecv (alaw)>
[Oct 20 18:19:13] DEBUG[2489556] res_pjsip_session.c:  
[Oct 20 18:19:13] DEBUG[2489556] res_pjsip_session.c:  PJSIP/opensips-00000005 Event: TSX_STATE  Inv State: DISCONNCTD
[Oct 20 18:19:13] DEBUG[2489556] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE
[Oct 20 18:19:13] DEBUG[2489556] res_pjsip_session.c: The state change pertains to the endpoint 'opensips(PJSIP/opensips-00000005)'
[Oct 20 18:19:13] DEBUG[2489556] res_pjsip_session.c: The inv session does NOT have an invite_tsx
[Oct 20 18:19:13] DEBUG[2489556] res_pjsip_session.c: There is no transaction involved in this state change
[Oct 20 18:19:13] DEBUG[2489556] res_pjsip_session.c: The current inv state is DISCONNCTD
[Oct 20 18:19:13] DEBUG[2489556] res_pjsip_session.c: PJSIP/opensips-00000005: Source of transaction state change is RX_MSG
[Oct 20 18:19:13] DEBUG[2489556] res_pjsip_session.c: PJSIP/opensips-00000005: Received request
[Oct 20 18:19:13] DEBUG[2489556] res_pjsip_session.c:  PJSIP/opensips-00000005: Method is BYE
[Oct 20 18:19:13] DEBUG[2489556] res_pjsip_session.c:  PJSIP/opensips-00000005
[Oct 20 18:19:13] DEBUG[2489556] res_pjsip_session.c:  
[Oct 20 18:19:13] DEBUG[2489556] res_pjsip_session.c:  PJSIP/opensips-00000005 TSX State: Completed  Inv State: DISCONNCTD
[Oct 20 18:19:13] DEBUG[2489556] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Oct 20 18:19:13] DEBUG[2489556] res_pjsip_session.c: The state change pertains to the endpoint 'opensips(PJSIP/opensips-00000005)'
[Oct 20 18:19:13] DEBUG[2489556] res_pjsip_session.c: The inv session does NOT have an invite_tsx
[Oct 20 18:19:13] DEBUG[2489556] res_pjsip_session.c: The UAS BYE transaction involved in this state change is 0x7f538000c638
[Oct 20 18:19:13] DEBUG[2489556] res_pjsip_session.c: The current transaction state is Completed
[Oct 20 18:19:13] DEBUG[2489556] res_pjsip_session.c: The transaction state change event is RX_MSG
[Oct 20 18:19:13] DEBUG[2489556] res_pjsip_session.c: The current inv state is DISCONNCTD
[Oct 20 18:19:13] DEBUG[2489556] res_pjsip_session.c:  Nothing delayed
[Oct 20 18:19:13] DEBUG[2489556] res_pjsip_session.c:  PJSIP/opensips-00000005 TSX State: Completed  Inv State: DISCONNCTD
[Oct 20 18:19:13] DEBUG[2489556] res_pjsip_session.c:  Topology: Pending: (null topology)  Active:  <0:audio-0:audio:sendrecv (alaw)>
[Oct 20 18:19:13] DEBUG[2489556] res_pjsip_session.c:  
[Oct 20 18:19:13] DEBUG[2489556] chan_pjsip.c:  PJSIP/opensips-00000005
[Oct 20 18:19:13] DEBUG[2489556] chan_pjsip.c:  
[Oct 20 18:19:13] DEBUG[2491029][C-00000006] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Oct 20 18:19:13] DEBUG[2491029][C-00000006] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Oct 20 18:19:13] DEBUG[2491029][C-00000006] channel.c: Channel PJSIP/opensips-00000005 setting write format path: alaw -> alaw
[Oct 20 18:19:13] DEBUG[2491029][C-00000006] channel.c: Channel PJSIP/opensips-00000005 setting read format path: alaw -> slin
[Oct 20 18:19:13] DEBUG[2491029][C-00000006] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21
[Oct 20 18:19:13] DEBUG[2491029][C-00000006] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116
[Oct 20 18:19:19] DEBUG[2382333] res_pjsip_session.c:  opensips TSX State: Terminated  Inv State: DISCONNCTD
[Oct 20 18:19:19] DEBUG[2382333] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Oct 20 18:19:19] DEBUG[2382333] res_pjsip_session.c: The state change pertains to the endpoint 'opensips()'
[Oct 20 18:19:19] DEBUG[2382333] res_pjsip_session.c: The inv session does NOT have an invite_tsx
[Oct 20 18:19:19] DEBUG[2382333] res_pjsip_session.c: The UAS BYE transaction involved in this state change is 0x7f5380020588
[Oct 20 18:19:19] DEBUG[2382333] res_pjsip_session.c: The current transaction state is Terminated
[Oct 20 18:19:19] DEBUG[2382333] res_pjsip_session.c: The transaction state change event is TIMER
[Oct 20 18:19:19] DEBUG[2382333] res_pjsip_session.c: The current inv state is DISCONNCTD
[Oct 20 18:19:19] DEBUG[2382333] res_pjsip_session.c:  Disconnected
[Oct 20 18:19:19] DEBUG[2382333] res_pjsip_session.c:  (null session) TSX State: Terminated  Inv State: DISCONNCTD
[Oct 20 18:19:19] DEBUG[2382333] res_pjsip_session.c:  
[Oct 20 18:19:19] DEBUG[2489556] res_pjsip_session.c: opensips: Destroying SIP session
[Oct 20 18:19:38] DEBUG[2382345] res_pjsip_registrar.c: Woke up at 1634743178  Interval: 30
[Oct 20 18:19:38] DEBUG[2382345] res_pjsip_registrar.c: Expiring 0 contacts
[Oct 20 18:19:45] DEBUG[2382333] res_pjsip_session.c:  PJSIP/opensips-00000005 TSX State: Terminated  Inv State: DISCONNCTD
[Oct 20 18:19:45] DEBUG[2382333] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[Oct 20 18:19:45] DEBUG[2382333] res_pjsip_session.c: The state change pertains to the endpoint 'opensips(PJSIP/opensips-00000005)'
[Oct 20 18:19:45] DEBUG[2382333] res_pjsip_session.c: The inv session does NOT have an invite_tsx
[Oct 20 18:19:45] DEBUG[2382333] res_pjsip_session.c: The UAS BYE transaction involved in this state change is 0x7f538000c638
[Oct 20 18:19:45] DEBUG[2382333] res_pjsip_session.c: The current transaction state is Terminated
[Oct 20 18:19:45] DEBUG[2382333] res_pjsip_session.c: The transaction state change event is TIMER
[Oct 20 18:19:45] DEBUG[2382333] res_pjsip_session.c: The current inv state is DISCONNCTD
[Oct 20 18:19:45] DEBUG[2382333] res_pjsip_session.c:  Disconnected
[Oct 20 18:19:45] DEBUG[2382333] res_pjsip_session.c:  (null session) TSX State: Terminated  Inv State: DISCONNCTD
[Oct 20 18:19:45] DEBUG[2382333] res_pjsip_session.c:  
[Oct 20 18:20:08] DEBUG[2382345] res_pjsip_registrar.c: Woke up at 1634743208  Interval: 30
[Oct 20 18:20:08] DEBUG[2382345] res_pjsip_registrar.c: Expiring 0 contacts
[Oct 20 18:20:31] DEBUG[2490678] threadpool.c: Worker thread idle timeout reached. Dying.
[Oct 20 18:20:31] DEBUG[2382302] threadpool.c: Destroying worker thread 22
[Oct 20 18:20:38] DEBUG[2382345] res_pjsip_registrar.c: Woke up at 1634743238  Interval: 30
[Oct 20 18:20:38] DEBUG[2382345] res_pjsip_registrar.c: Expiring 0 contacts
[Oct 20 18:20:45] DEBUG[2489556] threadpool.c: Worker thread idle timeout reached. Dying.
[Oct 20 18:20:45] DEBUG[2382331] threadpool.c: Destroying worker thread 16
[Oct 20 18:21:08] DEBUG[2382345] res_pjsip_registrar.c: Woke up at 1634743268  Interval: 30
[Oct 20 18:21:08] DEBUG[2382345] res_pjsip_registrar.c: Expiring 0 contacts
[Oct 20 18:21:13] DEBUG[2489562] threadpool.c: Worker thread idle timeout reached. Dying.
[Oct 20 18:21:13] DEBUG[2382302] threadpool.c: Destroying worker thread 21
[Oct 20 18:21:38] DEBUG[2382345] res_pjsip_registrar.c: Woke up at 1634743298  Interval: 30
[Oct 20 18:21:38] DEBUG[2382345] res_pjsip_registrar.c: Expiring 0 contacts
[Oct 20 18:22:08] DEBUG[2382345] res_pjsip_registrar.c: Woke up at 1634743328  Interval: 30
[Oct 20 18:22:08] DEBUG[2382345] res_pjsip_registrar.c: Expiring 0 contacts
[Oct 20 18:22:13] DEBUG[2491029][C-00000006] app_record.c: Got hangup
[Oct 20 18:22:13] DEBUG[2491029][C-00000006] channel.c: Channel PJSIP/opensips-00000005 setting read format path: alaw -> alaw
[Oct 20 18:22:13] DEBUG[2491029][C-00000006] pbx.c: Extension s, priority 11 returned normally even though call was hung up
[Oct 20 18:22:13] DEBUG[2491029][C-00000006] channel.c: Soft-Hanging (0x10) up channel 'PJSIP/opensips-00000005'
[Oct 20 18:22:13] DEBUG[2491029][C-00000006] channel.c: Soft-Hanging (0x80) up channel 'PJSIP/opensips-00000005'
[Oct 20 18:22:13] DEBUG[2491029][C-00000006] pbx_variables.c: Result of 'FaxStart' is '0'
[Oct 20 18:22:13] DEBUG[2491029][C-00000006] pbx_variables.c: Expression result is '0'
[Oct 20 18:22:13] DEBUG[2491029][C-00000006] pbx.c: Launching 'GotoIf'
[Oct 20 18:22:13] VERBOSE[2491029][C-00000006] pbx.c: Executing [h@recording:1] GotoIf("PJSIP/opensips-00000005", "0?check_fax") in new stack
[Oct 20 18:22:13] DEBUG[2491029][C-00000006] pbx_builtins.c: Not taking any branch
[Oct 20 18:22:13] DEBUG[2491029][C-00000006] pbx_variables.c: Result of 'RECORD_STATUS' is 'HANGUP'
[Oct 20 18:22:13] DEBUG[2491029][C-00000006] pbx_variables.c: Expression result is '1'
[Oct 20 18:22:13] DEBUG[2491029][C-00000006] pbx.c: Launching 'GotoIf'
[Oct 20 18:22:13] VERBOSE[2491029][C-00000006] pbx.c: Executing [h@recording:2] GotoIf("PJSIP/opensips-00000005", "1?check_duration:abort_deposit") in new stack
[Oct 20 18:22:13] DEBUG[2382302] threadpool.c: Increasing threadpool stasis/pool's size by 1
[Oct 20 18:22:13] VERBOSE[2491029][C-00000006] pbx_builtins.c: Goto (recording,h,3)
[Oct 20 18:22:13] DEBUG[2491029][C-00000006] pbx_variables.c: Result of 'wav_file' is 'Voicemail.wav'
[Oct 20 18:22:13] DEBUG[2491029][C-00000006] pbx_variables.c: Function SHELL(/usr/bin/soxi -D Voicemail.wav) result is '0.000000
'
[Oct 20 18:22:13] DEBUG[2491029][C-00000006] pbx.c: Launching 'Set'
[Oct 20 18:22:13] VERBOSE[2491029][C-00000006] pbx.c: Executing [h@recording:3] Set("PJSIP/opensips-00000005", "vmail_duration=0.000000
") in new stack
[Oct 20 18:22:13] DEBUG[2491029][C-00000006] pbx_variables.c: Result of 'vmail_duration' is '0.000000
'

It seems to me that this is an error behavior of Record(). Maybe it is associated with the ‘beep’ playback from Record(). When the hangup is received on ‘beep’, we got this error.

Could the experts please investigate and provide your feedback? How should I proceed?
Thank you.

4

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