Why is this command not always run?

After running the fax server for years I had to reimplement it massively, which made me write the following dialplan:

[fax_caller3]
; Start
exten => faxout,1,NoOp(** Fax caller **)
same => n,Dial(${ChannelPrefix}:${ReceiverPhoneNr}@${ChannelPostfix},,gb(fax_outgoing_init^faxout^1(${SenderPhoneNr},${ChannelPostfix})))

; Sending fax
exten => faxsend,1,NoOp(** Sending fax **)
same => n,Set(FAXOPT(headerinfo)=${FaxHeader})
same => n,Set(FAXOPT(localstationid)=${SenderName})
same => n,Set(FAXOPT(ecm)=yes)
same => n,SendFax(${TIFF_FILE},dfsz)
same => n,System(/opt/write_log.sh faxstatus '${UniqId}' '${FAXOPT(status)}' '${FAXOPT(statusstr)}')
same => n,Gosub(dlrsend, 1(${FAXOPT(status)}, ${FAXOPT(pages)}))

; Delivery notification
exten => dlrsend,1,NoOp(** Sending Delivery Notification **)
same => n,Set(status=${ARG1})
same => n,Set(pages=${ARG2})
same => n,System(/opt/callfinal.php -i '${UniqId}' -s '${status}' -p '${pages}' -t '${STRFTIME(${EPOCH},,%Y-%m-%d %H:%M:%S)}')
same => n,Return()

; Hangup
exten => h,1,NoOp(** Hung up **)
same => n,Gosub(dlrsend,1(failed,0))

; Failed
exten => failed,1,NoOp(** Fax failed **)
same => n,Gosub(dlrsend,1(failed,0))

[fax_outgoing_init]
exten => faxout,1,NoOp(** Fax, pre-dial hook **)
same => n,Set(PJSIP_HEADER(add,P-Preferred-Identity)="<sip:${ARG1}@${ARG2}>")
same => n,Return()

The extension faxsend, priority 1 is referred to within the callfile, all other variables like UniqId, ReceiverPhoneNr, too.

Now, my problem is that I have a call that was obviously successful:

Apr  7 14:15:49 v-dmz-fax3 asterisk[46338]: FAX[2050][C-0000001e]: res_fax.c:1037 in ast_fax_log: FLOW T.30 Success - delivered 3 pages
Apr  7 14:15:49 v-dmz-fax3 asterisk[46338]: VERBOSE[2050][C-0000001e]: res_fax.c:599 in debug_check_frame_for_silence: Channel 'Local/faxout@fax_caller3-0000000e;1' fax session '14', [ 090.955861 ],
 channel sent 67 frames (1340 ms) of energy.
Apr  7 14:15:49 v-dmz-fax3 asterisk[46338]: FAX[2050][C-0000001e]: res_fax.c:1037 in ast_fax_log: FLOW T.30 HDLC signal status is Carrier down (-1) in state 3
Apr  7 14:15:49 v-dmz-fax3 asterisk[46338]: FAX[2050][C-0000001e]: res_fax.c:1037 in ast_fax_log: FLOW T.30 Changing from phase T30_PHASE_D_RX to T30_PHASE_D_TX
Apr  7 14:15:49 v-dmz-fax3 asterisk[46338]: FAX[2050][C-0000001e]: res_fax.c:1037 in ast_fax_log: FLOW FAX Set rx type 0
Apr  7 14:15:49 v-dmz-fax3 asterisk[46338]: FAX[2050][C-0000001e]: res_fax.c:1037 in ast_fax_log: FLOW FAX Set tx type 4
Apr  7 14:15:49 v-dmz-fax3 asterisk[46338]: VERBOSE[2050][C-0000001e]: res_fax.c:599 in debug_check_frame_for_silence: Channel 'Local/faxout@fax_caller3-0000000e;1' fax session '14', [ 091.020170 ],
 stack sent 118 frames (2360 ms) of silence.
Apr  7 14:15:50 v-dmz-fax3 asterisk[46338]: FAX[2050][C-0000001e]: res_fax.c:1037 in ast_fax_log: FLOW T.30 Send complete in phase T30_PHASE_D_TX, state 3
Apr  7 14:15:50 v-dmz-fax3 asterisk[46338]: FAX[2050][C-0000001e]: res_fax.c:1037 in ast_fax_log: FLOW T.30 Send complete in phase T30_PHASE_D_TX, state 3
Apr  7 14:15:50 v-dmz-fax3 asterisk[46338]: FAX[2050][C-0000001e]: res_fax.c:1037 in ast_fax_log: FLOW T.30 Starting final pause before disconnecting
Apr  7 14:15:50 v-dmz-fax3 asterisk[46338]: FAX[2050][C-0000001e]: res_fax.c:1037 in ast_fax_log: FLOW T.30 Changing from phase T30_PHASE_D_TX to T30_PHASE_E
Apr  7 14:15:50 v-dmz-fax3 asterisk[46338]: FAX[2050][C-0000001e]: res_fax.c:1037 in ast_fax_log: FLOW FAX Set rx type 0
Apr  7 14:15:50 v-dmz-fax3 asterisk[46338]: FAX[2050][C-0000001e]: res_fax.c:1037 in ast_fax_log: FLOW FAX Set tx type 1
Apr  7 14:15:50 v-dmz-fax3 asterisk[46338]: FAX[2050][C-0000001e]: res_fax.c:1037 in ast_fax_log: FLOW T.30 Changing from state 3 to 2
Apr  7 14:15:50 v-dmz-fax3 asterisk[46338]: VERBOSE[2050][C-0000001e]: res_fax.c:599 in debug_check_frame_for_silence: Channel 'Local/faxout@fax_caller3-0000000e;1' fax session '14', [ 092.140167 ], stack sent 56 frames (1120 ms) of energy.
Apr  7 14:15:51 v-dmz-fax3 asterisk[46338]: VERBOSE[2050][C-0000001e]: res_fax.c:599 in debug_check_frame_for_silence: Channel 'Local/faxout@fax_caller3-0000000e;1' fax session '14', [ 092.555628 ], channel sent 80 frames (1600 ms) of silence.
Apr  7 14:15:51 v-dmz-fax3 asterisk[46338]: VERBOSE[2050][C-0000001e]: res_fax.c:599 in debug_check_frame_for_silence: Channel 'Local/faxout@fax_caller3-0000000e;1' fax session '14', [ 092.655770 ], channel sent 5 frames (100 ms) of energy.
Apr  7 14:15:51 v-dmz-fax3 asterisk[46338]: VERBOSE[2050][C-0000001e]: res_fax.c:599 in debug_check_frame_for_silence: Channel 'Local/faxout@fax_caller3-0000000e;1' fax session '14', [ 092.675738 ], channel sent 1 frames (20 ms) of silence.
Apr  7 14:15:51 v-dmz-fax3 asterisk[46338]: VERBOSE[2050][C-0000001e]: res_fax.c:599 in debug_check_frame_for_silence: Channel 'Local/faxout@fax_caller3-0000000e;1' fax session '14', [ 092.735639 ], channel sent 3 frames (60 ms) of energy.
Apr  7 14:15:51 v-dmz-fax3 asterisk[46338]: VERBOSE[2050][C-0000001e]: res_fax.c:599 in debug_check_frame_for_silence: Channel 'Local/faxout@fax_caller3-0000000e;1' fax session '14', [ 092.777775 ], channel sent 1 frames (20 ms) of silence.
Apr  7 14:15:51 v-dmz-fax3 asterisk[46338]: VERBOSE[2050][C-0000001e]: res_fax.c:599 in debug_check_frame_for_silence: Channel 'Local/faxout@fax_caller3-0000000e;1' fax session '14', [ 092.795680 ], channel sent 2 frames (40 ms) of energy.
Apr  7 14:15:51 v-dmz-fax3 asterisk[46338]: FAX[2050][C-0000001e]: res_fax.c:1037 in ast_fax_log: FLOW T.30 Changing from state 2 to 30
Apr  7 14:15:51 v-dmz-fax3 asterisk[46338]: FAX[2050][C-0000001e]: res_fax.c:1037 in ast_fax_log: FLOW T.30 Changing from phase T30_PHASE_E to T30_PHASE_CALL_FINISHED
Apr  7 14:15:51 v-dmz-fax3 asterisk[46338]: FAX[2050][C-0000001e]: res_fax.c:1037 in ast_fax_log: FLOW FAX Set rx type 9
Apr  7 14:15:51 v-dmz-fax3 asterisk[46338]: FAX[2050][C-0000001e]: res_fax.c:1037 in ast_fax_log: FLOW FAX FAX exchange complete
Apr  7 14:15:51 v-dmz-fax3 asterisk[46338]: FAX[2050][C-0000001e]: res_fax.c:1037 in ast_fax_log: FLOW FAX Set tx type 9
Apr  7 14:15:51 v-dmz-fax3 asterisk[46338]: FAX[2050][C-0000001e]: res_fax.c:1037 in ast_fax_log: FLOW FAX FAX exchange complete
Apr  7 14:15:51 v-dmz-fax3 asterisk[46338]: FAX[2050][C-0000001e]: res_fax.c:1037 in ast_fax_log: FLOW T.30 Call completed
Apr  7 14:15:51 v-dmz-fax3 asterisk[46338]: NOTICE[2050][C-0000001e]: pbx_spool.c:463 in attempt_thread: Call completed to Local/faxout@fax_caller3

However, the following command System(write_log.sh) was not launched at all, neither was System(callfinal.php) (which should be executed because of the following Gosub) . So, my question is: How come, and what do I have to do to ensure that all commands after SendFax are always executed, no matter if the fax fails or succeeds?

Note: Both these processes to be called write something to the syslog, so I can see that neither was launched.

There is no guarantee that a channel will remain up after fax sending is complete. To that end people use the “h” extension or hangup handlers[1] to execute logic on hangup.

[1] https://wiki.asterisk.org/wiki/display/AST/Hangup+Handlers

So I have to push a hangup handler before invoking SendFax. Are functions in arguments evaluated on execution of the handler?

But if I prepend

same => n,Set(CHANNEL(hangup_handler_push)=dlrsend,1({FAXOPT(status)}, {FAXOPT(statusstr)})

and removing the two commands after SendFax (invoking write_log.sh is not really necessary, it was done for debugging, but callfinal.php must be invoked), it does not work because FAXOPT is not evaluated on invocation. How do I accomplish this?

@jcolp, thank you.

This seems to be the solution:

same => n,Set(CHANNEL(hangup_handler_push)=faxfinal,1())
same => n,SendFax(${TIFF_FILE},dfsz)

exten => faxfinal,1,NoOp(** Fax call finished **)
same => n,Gosub(dlrsend, 1(${FAXOPT(status)},${FAXOPT(pages)}))
same => n,Return()

On the other hand, much simpler - bump:

[fax_caller3]
; Start
exten => faxout,1,NoOp(** Fax caller **)
same => n,Dial(${ChannelPrefix}:${ReceiverPhoneNr}@${ChannelPostfix},,gb(fax_outgoing_init^faxout^1(${SenderPhoneNr},${ChannelPostfix})))

; Sending fax
exten => faxsend,1,NoOp(** Sending fax **)
same => n,Set(FAXOPT(headerinfo)=${FaxHeader})
same => n,Set(FAXOPT(localstationid)=${SenderName})
same => n,Set(FAXOPT(ecm)=yes)
same => n,SendFax(${TIFF_FILE},dfsz)

; Delivery notification
exten => dlrsend,1,NoOp(** Sending Delivery Notification **)
same => n,Set(status=${ARG1})
same => n,Set(pages=${ARG2})
same => n,System(/opt/callfinal.php -i '${UniqId}' -s '${status}' -p '${pages}' -t '${STRFTIME(${EPOCH},,%Y-%m-%d %H:%M:%S)}')
same => n,Return()

; Hangup
exten => h,1,NoOp(** Hung up **)
same => n,Gosub(dlrsend,1(${FAXOPT(status)},${FAXOPT(pages)}))

; Failed
exten => failed,1,NoOp(** Fax failed **)
same => n,Gosub(dlrsend,1(failed,0))

This renders invocations to callfinal.php having empty arguments, but this does not matter, because callfinal.php treats an empty status as failed, an empty pages argument as not having been given at all. Also, this program is smart enough to handle the fact that it is called twice - once with SUCCESSand once with FAILED, preferring SUCCESS, no matter which order.

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