[Home]

Summary:ASTERISK-27082: res_fax: Error building JSON, Invalid UTF-8 string due to invalid FAX CSI string format
Reporter:Ludovic Gasc (Eyepea) (gmludo)Labels:
Date Opened:2017-06-22 16:23:42Date Closed:
Priority:MinorRegression?Yes
Status:Open/NewComponents:Resources/res_fax
Versions:13.16.0 Frequency of
Occurrence
Related
Issues:
is duplicated byASTERISK-28454 res_fax.c UTF-8 validation for remotestationid and pbx_builtin_setvar_helper
Environment:Debian 8Attachments:( 0) jira_asterisk_27082_v13_debug.patch
Description:Hi,

When we use SendFAX application, we have found a fax machine that stops prematurely Fax session.
It seems a character encoding issue:

The logs:
{noformat}
[Jun 22 09:52:07] FAX[24642][C-00000007]: res_fax.c:1039 ast_fax_log: FLOW T.38 Rx    82: (0) data v21/hdlc-fcs-OK-sig-end + 0 byte(s)
[Jun 22 09:52:07] FAX[24642][C-00000007]: res_fax.c:1039 ast_fax_log: FLOW T.38T Type CSI - CRC OK, sig end (clean)
[Jun 22 09:52:07] FAX[24642][C-00000007]: res_fax.c:1039 ast_fax_log: FLOW T.30 Stop T4 (13840 remaining)
[Jun 22 09:52:07] FAX[24642][C-00000007]: res_fax.c:1039 ast_fax_log: FLOW T.30 Rx:  CSI without final frame tag
[Jun 22 09:52:07] FAX[24642][C-00000007]: res_fax.c:1039 ast_fax_log: FLOW T.30 Rx:  ff 03 40 36 32 ff 13 84
[Jun 22 09:52:07] FAX[24642][C-00000007]: res_fax.c:1039 ast_fax_log: FLOW T.30 Remote gave CSI as: "��26"
[Jun 22 09:52:07] FAX[24642][C-00000007]: res_fax.c:1039 ast_fax_log: FLOW T.30 HDLC signal status is Carrier down (-1) in state 6
[Jun 22 09:52:07] FAX[24642][C-00000007]: res_fax.c:1039 ast_fax_log: FLOW T.30 HDLC signal status is Carrier down (-1) in state 6
[Jun 22 09:52:07] FAX[24642][C-00000007]: res_fax.c:1039 ast_fax_log: FLOW T.30 No signal is present
[Jun 22 09:52:07] FAX[24642][C-00000007]: res_fax.c:1039 ast_fax_log: FLOW T.38 Rx    83: IFP 00
[Jun 22 09:52:07] FAX[24642][C-00000007]: res_fax.c:1039 ast_fax_log: FLOW T.38 Rx    83: indicator no-signal
[Jun 22 09:52:33] FAX[24642][C-00000007]: res_fax.c:1039 ast_fax_log: FLOW T.30 Status changing to 'The call dropped prematurely'
[Jun 22 09:52:33] FAX[24642][C-00000007]: res_fax.c:1039 ast_fax_log: FLOW T.30 Changing from state 6 to 30
[Jun 22 09:52:33] FAX[24642][C-00000007]: res_fax.c:1039 ast_fax_log: FLOW T.30 Changing from phase T30_PHASE_B_RX to T30_PHASE_CALL_FINISHED
[Jun 22 09:52:33] FAX[24642][C-00000007]: res_fax.c:1039 ast_fax_log: FLOW T.38T Set rx type 9
[Jun 22 09:52:33] FAX[24642][C-00000007]: res_fax.c:1039 ast_fax_log: FLOW T.38T Set tx type 9
[Jun 22 09:52:33] FAX[24642][C-00000007]: res_fax.c:1039 ast_fax_log: FLOW T.38T FAX exchange complete
[Jun 22 09:52:33] FAX[24642][C-00000007]: res_fax.c:1039 ast_fax_log: FLOW T.30 Call completed
[Jun 22 09:52:33] ERROR[24642][C-00000007]: json.c:825 ast_json_vpack: Error building JSON from '{s: s, s: s}': Invalid UTF-8 string.
[Jun 22 09:52:33] ERROR[24642][C-00000007]: stasis_channels.c:771 ast_channel_publish_varset: Error creating message
[Jun 22 09:52:33] ERROR[24642][C-00000007]: json.c:825 ast_json_vpack: Error building JSON from '{s: s, s: s, s: s, s: s, s: s, s: s, s: o}': Invalid UTF-8 string.
[Jun 22 09:52:33] ERROR[24642][C-00000007]: res_fax.c:2808 sendfax_exec: Error publishing SendFAX status message
{noformat}
We have the PCAP, but we can't share publicly on the Internet.

The strange thing, is that we don't seem to have this issue with another server with Asterisk 13.15. But, for an unknown reason, it doesn't use T.38 for the same number:
{noformat}
[Jun 22 12:40:56] FAX[7619][C-00000037]: res_fax.c:1039 ast_fax_log: FLOW T.30 The remote was made in 'Japan'
[Jun 22 12:40:56] FAX[7619][C-00000037]: res_fax.c:1039 ast_fax_log: FLOW T.30 The remote was made by 'Brother'
[Jun 22 12:40:56] FAX[7619][C-00000037]: res_fax.c:1039 ast_fax_log: FLOW T.30 Stop none (0 remaining)
[Jun 22 12:40:56] FAX[7619][C-00000037]: res_fax.c:1039 ast_fax_log: FLOW T.30 Rx:  CSI without final frame tag
[Jun 22 12:40:56] FAX[7619][C-00000037]: res_fax.c:1039 ast_fax_log: FLOW T.30 Rx:  ff 03 40 36 32 30 39 35 35 33 32 32 33 2b 20 20 20 20 20 20 20 20 20
[Jun 22 12:40:56] FAX[7619][C-00000037]: res_fax.c:1039 ast_fax_log: FLOW T.30 Remote gave CSI as: "+3223559026"
{noformat}
Comments:By: Asterisk Team (asteriskteam) 2017-06-22 16:23:43.034-0500

Thanks for creating a report! The issue has entered the triage process. That means the issue will wait in this status until a Bug Marshal has an opportunity to review the issue. Once the issue has been reviewed you will receive comments regarding the next steps towards resolution.

A good first step is for you to review the [Asterisk Issue Guidelines|https://wiki.asterisk.org/wiki/display/AST/Asterisk+Issue+Guidelines] if you haven't already. The guidelines detail what is expected from an Asterisk issue report.

Then, if you are submitting a patch, please review the [Patch Contribution Process|https://wiki.asterisk.org/wiki/display/AST/Patch+Contribution+Process].
By: Rusty Newton (rnewton) 2017-06-26 14:29:07.890-0500

Can you attach a debug log?

https://wiki.asterisk.org/wiki/display/AST/Collecting+Debug+Information

Feel free to sanitize as needed. Otherwise, you can send it and the pcap to asteriskteam at digium.com.

To clarify, this issue only began occurring when you moved from 13.15 to 13.16? Or are the 13.15 and 13.16 machines completely separate systems? If so, do they have identical configuration other than the version difference?
By: Ludovic Gasc (Eyepea) (gmludo) 2017-06-27 04:50:10.972-0500

> Can you attach a debug log?
> Otherwise, you can send it and the pcap to asteriskteam at digium.com.

I've sent pcap file on  asteriskteam at digium.com.
However, I don't have more logs than in this issue.

> To clarify, this issue only began occurring when you moved from 13.15 to 13.16?

Yes, it's when we are moving our platform from 13.15 to 13.16, however, I'm sorry, but it was a wrong clue: We didn't reproduce this issue again with 13.16.
It seems more a random problem from the operator at one moment, certainly we should have the same issue with 13.15 if we have sent the same fax at same time.

However, you might protect Asterisk against this character encoding error spotted in this log trace.
By: Sean Bright (seanbright) 2017-06-27 08:40:12.414-0500

Quoting from Recommendation T.30:

{quote}
The facsimile information field of the CSI signal shall be the international telephone number
including the "+" character, the telephone country code, area code and subscriber number. This field
shall consist of 20 numeric digits coded as shown in Table 3 but excluding the "*" and "#"
characters. The least significant bit of the least significant digit shall be the first bit transmitted.
{quote}

This looks like an error on the sender's side
By: Richard Mudgett (rmudgett) 2017-06-27 19:34:25.940-0500

[^jira_asterisk_27082_v13_debug.patch] - Patch to add a backtrace to the log to find out who is trying to generate a JSON object but supplying an "Invalid UTF-8 string".

To use enable BETTER_BACKTRACES and reproduce the issue.  Attach the log to the issue with a .txt exten.
By: Ludovic Gasc (Eyepea) (gmludo) 2017-06-28 05:56:08.938-0500

> This looks like an error on the sender's side

I'm not a T.30 specialist, however, I can confirm you that this trace was made from the Asterisk SendFAX application to +3223559026.

If I understand correctly the log message "Remote gave CSI as: "��26" " comes from the receiver.

> Patch to add a backtrace to the log to find out who is trying to generate a JSON object but supplying an "Invalid UTF-8 string".

Thanks for the patch, however, we didn't arrive yet to reproduce for now.

We will apply your patch and waiting the next issue for that.
By: Ludovic Gasc (Eyepea) (gmludo) 2017-07-07 18:16:26.626-0500

Hi Asterisk Team,

I'm really sorry, but we never have again this bug on production, event with the fax machine we had the bug.
For me, you can close.

Regards.
By: Rusty Newton (rnewton) 2017-07-07 18:24:07.404-0500

[~gmludo] , no worries. We are closing this out as unable to reproduce.

However, [~rmudgett] will submit the diagnostic patch for review so that we can possibly catch this in the future and have the data we need to track it down.

Thanks!
By: Ludovic Gasc (Eyepea) (gmludo) 2017-07-10 04:38:46.238-0500

You're welcome.

I've checked in our faxes logs since two weeks, no more issues like that.
I'll re-open in case of it respawns in one moment.

Thanks for your time.
By: Asterisk Team (asteriskteam) 2017-07-10 04:38:46.612-0500

This issue has been reopened as a result of your commenting on it as the reporter. It will be triaged once again as applicable.
By: Ross Beer (rossbeer) 2017-07-17 13:14:58.674-0500

After installing the patch I get the following backtrace when receiving faxes:


{noformat}
[Jul 17 17:46:15] ERROR[28545][C-000004c0]: json.c:825 ast_json_vpack: Error building JSON from '{s: s, s: s}': Invalid UTF-8 string.
Got 18 backtrace records
#0: [0x532433] main/json.c:831 ast_json_vpack() (0x53237e+B5)
#1: [0x53236e] main/json.c:814 ast_json_pack() (0x5322cf+9F)
#2: [0x5d1c9d] main/stasis_channels.c:767 ast_channel_publish_varset() (0x5d1c62+3B)
#3: [0x589adc] main/pbx_variables.c:1070 pbx_builtin_setvar_helper() (0x58979a+342)
#4: [0x7f56860715eb] res/res_fax.c:1450 set_channel_variables()
#5: [0x7f5686076628] res/res_fax.c:1825 generic_fax_exec()
#6: [0x7f568607b5a5] res/res_fax.c:2260 receivefax_exec()
#7: [0x580014] main/pbx_app.c:491 pbx_exec() (0x57fef8+11C)
#8: [0x56d96e] main/pbx.c:2884 pbx_extension_helper()
#9: [0x570e21] main/pbx.c:4110 ast_spawn_extension() (0x570dbd+64)
#10: [0x571adc] main/pbx.c:4286 __ast_pbx_run()
#11: [0x57328b] main/pbx.c:4609 pbx_thread()
#12: [0x5f762e] main/utils.c:1238 dummy_start()
[Jul 17 17:46:15] ERROR[28545][C-000004c0]: stasis_channels.c:771 ast_channel_publish_varset: Error creating message
[Jul 17 17:46:15] ERROR[28545][C-000004c0]: json.c:825 ast_json_vpack: Error building JSON from '{s: s, s: s, s: s, s: s, s: s, s: s, s: o}': Invalid UTF-8 string.
Got 15 backtrace records
#0: [0x532433] main/json.c:831 ast_json_vpack() (0x53237e+B5)
#1: [0x53236e] main/json.c:814 ast_json_pack() (0x5322cf+9F)
#2: [0x7f568607761b] res/res_fax.c:2055 report_receive_fax_status()
#3: [0x7f568607b690] res/res_fax.c:2270 receivefax_exec()
#4: [0x580014] main/pbx_app.c:491 pbx_exec() (0x57fef8+11C)
#5: [0x56d96e] main/pbx.c:2884 pbx_extension_helper()
#6: [0x570e21] main/pbx.c:4110 ast_spawn_extension() (0x570dbd+64)
#7: [0x571adc] main/pbx.c:4286 __ast_pbx_run()
#8: [0x57328b] main/pbx.c:4609 pbx_thread()
#9: [0x5f762e] main/utils.c:1238 dummy_start()
[Jul 17 17:46:15] ERROR[28545][C-000004c0]: res_fax.c:2271 receivefax_exec: Error publishing ReceiveFax status message
{noformat}
By: Rusty Newton (rnewton) 2017-07-18 15:22:33.419-0500

Thanks to all who reported and the debug. With [~rossbeer]'s latest debug we can move forward with the issue when resources are available.
By: Ross Beer (rossbeer) 2017-07-25 02:29:21.016-0500

Further json issues:

{noformat}
[Jul 25 08:25:41] ERROR[32539][C-00000057]: json.c:825 ast_json_vpack: Error building JSON from '{s: s, s: s}': Invalid UTF-8 string.
Got 18 backtrace records
#0: [0x532a76] main/json.c:831 ast_json_vpack() (0x5329c1+B5)
#1: [0x5329b1] main/json.c:814 ast_json_pack() (0x532912+9F)
#2: [0x5d22e0] main/stasis_channels.c:767 ast_channel_publish_varset() (0x5d22a5+3B)
#3: [0x58a11f] main/pbx_variables.c:1070 pbx_builtin_setvar_helper() (0x589ddd+342)
#4: [0x7f99bd27c5eb] res/res_fax.c:1450 set_channel_variables()
#5: [0x7f99bd281628] res/res_fax.c:1825 generic_fax_exec()
#6: [0x7f99bd2865a5] res/res_fax.c:2260 receivefax_exec()
#7: [0x580657] main/pbx_app.c:491 pbx_exec() (0x58053b+11C)
#8: [0x56dfb1] main/pbx.c:2884 pbx_extension_helper()
#9: [0x571464] main/pbx.c:4110 ast_spawn_extension() (0x571400+64)
#10: [0x57211f] main/pbx.c:4286 __ast_pbx_run()
#11: [0x5738ce] main/pbx.c:4609 pbx_thread()
#12: [0x5f7c71] main/utils.c:1238 dummy_start()
[Jul 25 08:25:41] ERROR[32539][C-00000057]: stasis_channels.c:771 ast_channel_publish_varset: Error creating message
{noformat}

{noformat}
[Jul 25 08:25:41] ERROR[32539][C-00000057]: json.c:825 ast_json_vpack: Error building JSON from '{s: s, s: s, s: s, s: s, s: s, s: s, s: o}': Invalid UTF-8 string.
Got 15 backtrace records
#0: [0x532a76] main/json.c:831 ast_json_vpack() (0x5329c1+B5)
#1: [0x5329b1] main/json.c:814 ast_json_pack() (0x532912+9F)
#2: [0x7f99bd28261b] res/res_fax.c:2055 report_receive_fax_status()
#3: [0x7f99bd286690] res/res_fax.c:2270 receivefax_exec()
#4: [0x580657] main/pbx_app.c:491 pbx_exec() (0x58053b+11C)
#5: [0x56dfb1] main/pbx.c:2884 pbx_extension_helper()
#6: [0x571464] main/pbx.c:4110 ast_spawn_extension() (0x571400+64)
#7: [0x57211f] main/pbx.c:4286 __ast_pbx_run()
#8: [0x5738ce] main/pbx.c:4609 pbx_thread()
#9: [0x5f7c71] main/utils.c:1238 dummy_start()
[Jul 25 08:25:41] ERROR[32539][C-00000057]: res_fax.c:2271 receivefax_exec: Error publishing ReceiveFax status message
{noformat}
By: Richard Mudgett (rmudgett) 2017-07-25 09:59:12.582-0500

[~rossbeer] These last two inline backtraces are *exactly* the same as the first two you posted.  You don't need to post the same thing again.  These are happening during a received fax.  The original reporter's invalid UTF-8 errors happened for a sent fax.  The only thing we will be able to do with this issue is to prevent the invalid UTF-8 errors when creating a JSON object.
By: Michael Keuter (mkeuter) 2018-11-06 07:38:09.178-0600

I had similar error messages when receiving a Fax and the variable $\{REMOTESTATIONID} contained a German umlaut "L�beck" in Asterisk 13.23.1.

{noformat}
[Nov  6 14:15:56] WARNING[6059][C-00002946] res_fax_spandsp.c: WARNING T.30 ECM carrier not found
[Nov  6 14:15:56] WARNING[6059][C-00002946] res_fax_spandsp.c: WARNING T.30 ECM carrier not found
[Nov  6 14:16:02] ERROR[6059][C-00002946] json.c: Error building JSON from '{s: s, s: s}': Invalid UTF-8 string.
[Nov  6 14:16:02] VERBOSE[6059][C-00002946] logger.c: Got 16 backtrace records
[Nov  6 14:16:02] VERBOSE[6059][C-00002946] logger.c: #0: [0x52c77c] /usr/sbin/asterisk(ast_json_pack+0x8c) [0x52c77c]
[Nov  6 14:16:02] VERBOSE[6059][C-00002946] logger.c: #1: [0x5c7805] /usr/sbin/asterisk(ast_channel_publish_varset+0x25) [0x5c7805]
[Nov  6 14:16:02] VERBOSE[6059][C-00002946] logger.c: #2: [0x586063] /usr/sbin/asterisk(pbx_builtin_setvar_helper+0x113) [0x586063]
[Nov  6 14:16:02] VERBOSE[6059][C-00002946] logger.c: #3: [0x2aefac004602] /usr/lib/asterisk/modules/res_fax.so(+0x4602) [0x2aefac004602]
[Nov  6 14:16:02] VERBOSE[6059][C-00002946] logger.c: #4: [0x2aefac009774] /usr/lib/asterisk/modules/res_fax.so(+0x9774) [0x2aefac009774]
[Nov  6 14:16:02] VERBOSE[6059][C-00002946] logger.c: #5: [0x2aefac00f15c] /usr/lib/asterisk/modules/res_fax.so(+0xf15c) [0x2aefac00f15c]
[Nov  6 14:16:02] VERBOSE[6059][C-00002946] logger.c: #6: [0x57d749] /usr/sbin/asterisk(pbx_exec+0xb9) [0x57d749]
[Nov  6 14:16:02] VERBOSE[6059][C-00002946] logger.c: #7: [0x572479] /usr/sbin/asterisk() [0x572479]
[Nov  6 14:16:02] VERBOSE[6059][C-00002946] logger.c: #8: [0x57439b] /usr/sbin/asterisk() [0x57439b]
[Nov  6 14:16:02] VERBOSE[6059][C-00002946] logger.c: #9: [0x57592b] /usr/sbin/asterisk() [0x57592b]
[Nov  6 14:16:02] VERBOSE[6059][C-00002946] logger.c: #10: [0x5e7baa] /usr/sbin/asterisk() [0x5e7baa]
[Nov  6 14:16:02] ERROR[6059][C-00002946] stasis_channels.c: Error creating message
[Nov  6 14:16:02] ERROR[6059][C-00002946] json.c: Error building JSON from '{s: s, s: s, s: s, s: s, s: s, s: s, s: o}': Invalid UTF-8 string.
[Nov  6 14:16:02] VERBOSE[6059][C-00002946] logger.c: Got 13 backtrace records
[Nov  6 14:16:02] VERBOSE[6059][C-00002946] logger.c: #0: [0x52c77c] /usr/sbin/asterisk(ast_json_pack+0x8c) [0x52c77c]
[Nov  6 14:16:02] VERBOSE[6059][C-00002946] logger.c: #1: [0x2aefac005338] /usr/lib/asterisk/modules/res_fax.so(+0x5338) [0x2aefac005338]
[Nov  6 14:16:02] VERBOSE[6059][C-00002946] logger.c: #2: [0x2aefac00f1b1] /usr/lib/asterisk/modules/res_fax.so(+0xf1b1) [0x2aefac00f1b1]
[Nov  6 14:16:02] VERBOSE[6059][C-00002946] logger.c: #3: [0x57d749] /usr/sbin/asterisk(pbx_exec+0xb9) [0x57d749]
[Nov  6 14:16:02] VERBOSE[6059][C-00002946] logger.c: #4: [0x572479] /usr/sbin/asterisk() [0x572479]
[Nov  6 14:16:02] VERBOSE[6059][C-00002946] logger.c: #5: [0x57439b] /usr/sbin/asterisk() [0x57439b]
[Nov  6 14:16:02] VERBOSE[6059][C-00002946] logger.c: #6: [0x57592b] /usr/sbin/asterisk() [0x57592b]
[Nov  6 14:16:02] VERBOSE[6059][C-00002946] logger.c: #7: [0x5e7baa] /usr/sbin/asterisk() [0x5e7baa]
[Nov  6 14:16:02] ERROR[6059][C-00002946] res_fax.c: Error publishing ReceiveFax status message
{noformat}