Cannot send faxes with version 2.2.1 and FritzBox 7490

[firewiremb]

The attempt to send a fax via an analog connection is canceled with the error Phase E handler (0x12) Invalid response after sending a page

I tested the sending with three different fax receivers. The result was the same for everyone.

FRITZ!OS 07.21 / T.38 enabled
OS: Linux Mint 20.1 x86_64 (based on Ubuntu 20.04)
Roger Router 2.2.1 (flathub version)

Debug Log:

(18:18:15) INFO: rm 2.1.4
(18:18:15) DEBUG: rm_faxserver_init(): Fax Server running on port 9100
(18:18:15) DEBUG: rm_plugins_enable(): + AVM FRITZ!Box
(18:18:15) DEBUG: fritzbox_init_callmonitor(): called
(18:18:15) DEBUG: rm_device_register(): Registering Call Monitor
(18:18:15) DEBUG: rm_plugins_enable(): + CAPI
(18:18:15) DEBUG: rm_device_register(): Registering CAPI
(18:18:15) DEBUG: rm_phone_register(): Registering CAPI Softphone
(18:18:15) DEBUG: capi_fax_init(): called
(18:18:15) DEBUG: rm_fax_register(): Registering CAPI Fax
(18:18:15) DEBUG: rm_plugins_enable(): + Simples Passwort
(18:18:15) DEBUG: rm_plugins_enable(): + Secret
(18:18:15) DEBUG: secret_available(): Checking 'X-Cinnamon'/'cinnamon'
(18:18:15) DEBUG: secret_available(): No supported desktop environment (X-Cinnamon/cinnamon), secret will be disabled
(18:18:15) DEBUG: _g_io_module_get_default: Found default implementation portal (GNetworkMonitorPortal) for ‘gio-network-monitor’
(18:18:15) DEBUG: rm_ssdp_init(): Initialize upnp context manager
(18:18:15) DEBUG: Using context manager implementation GUPnPLinuxContextManager
(18:18:15) DEBUG: rm_netmonitor_state_changed(): Network state changed from offline to offline
(18:18:15) DEBUG: rm_netmonitor_state_changed(): Network state changed from offline to online
(18:18:15) DEBUG: _g_io_module_get_default: Found default implementation portal (GProxyResolverPortal) for ‘gio-proxy-resolver’
(18:18:15) DEBUG: _g_io_module_get_default: Found default implementation gnutls (GTlsBackendGnutls) for ‘gio-tls-backend’
(18:18:15) DEBUG: rm_router_present(): Got active router
(18:18:15) DEBUG: rm_profile_detect(): Configured router found: FRITZ!Box 7490
(18:18:15) DEBUG: rm_profile_detect(): Current router firmware: 113.7.21
(18:18:18) DEBUG: rm_netmonitor_state_changed(): Calling connect for 'Call Monitor'
(18:18:18) DEBUG: callmonitor_connect(): Trying to connect to '192.168.188.1' on port 1012
(18:18:18) DEBUG: callmonitor_connect(): Connected to '192.168.188.1' on port 1012
(18:18:18) DEBUG: rm_netmonitor_state_changed(): Calling connect for 'CAPI'
(18:18:18) DEBUG: capi_session_connect(): called
(18:18:18) DEBUG: Listen to controller #4 ...
(18:18:18) DEBUG: CAPI connection established!
(18:18:18) DEBUG: Bootstrap: Querying all interfaces
(18:18:18) DEBUG: Received RTM_NEWLINK
(18:18:18) DEBUG: Received RTM_NEWLINK
(18:18:18) DEBUG: Received RTM_NEWLINK
(18:18:18) DEBUG: Received RTM_NEWLINK
(18:18:18) DEBUG: rm_router_present(): Got active router
(18:18:18) DEBUG: fritzbox_set_active(): Settings created
(18:18:18) DEBUG: fritzbox_get_phone_list(): Adding 'ISDN: ISDN/DECT Rundruf'
(18:18:18) DEBUG: fritzbox_get_phone_list(): Adding 'DECT: Telefon'
(18:18:18) DEBUG: fritzbox_add_phone(): Adding 'ISDN: ISDN/DECT Rundruf'
(18:18:18) DEBUG: rm_phone_register(): Registering ISDN: ISDN/DECT Rundruf
(18:18:18) DEBUG: fritzbox_add_phone(): Adding 'DECT: Telefon'
(18:18:18) DEBUG: rm_phone_register(): Registering DECT: Telefon
(18:18:18) DEBUG: fritzbox_set_active(): TR-064 enabled
(18:18:18) DEBUG: rm_plugins_bind_loaded_plugins(): Called for profile
(18:18:18) DEBUG: rm_plugins_enable(): + Ortsvorwahl (Global)
(18:18:18) DEBUG: AreaCodes: '/app/lib/rm/areacodes_global/globalareacodes.csv'
(18:18:18) DEBUG: rm_plugins_enable(): + FritzFon
(18:18:18) DEBUG: rm_router_need_ftp(): ftp needed? 0
(18:18:18) DEBUG: rm_router_need_ftp(): ftp needed? 0
(18:18:18) DEBUG: fritzfon_read_book_tr64(): owner 0, name Telefonbuch
(18:18:18) DEBUG: Unhandled phone number type: 'intern'
(18:18:18) DEBUG: Unhandled phone number type: 'intern'
(18:18:18) DEBUG: Unhandled phone number type: 'memo'
(18:18:18) DEBUG: Unhandled phone number type: 'intern'
(18:18:18) DEBUG: Unhandled phone number type: 'intern'
(18:18:18) DEBUG: Unhandled phone number type: ''
(18:18:18) DEBUG: Unhandled phone number type: 'intern'
(18:18:18) DEBUG: Unhandled phone number type: 'intern'
(18:18:18) DEBUG: Unhandled phone number type: ''
(18:18:18) DEBUG: Unhandled phone number type: ''
(18:18:18) DEBUG: Unhandled phone number type: ''
(18:18:18) DEBUG: rm_plugins_enable(): + Rückwärtssuche
(18:18:18) DEBUG: ReverseLookup: '/app/lib/rm/reverselookup/lookup.xml'
(18:18:18) DEBUG: Country Code: 49
(18:18:18) DEBUG: o Service: '11880.com', prefix: 0
(18:18:18) DEBUG: o Service: 'klicktel.de', prefix: 0
(18:18:18) DEBUG: rm_plugins_enable(): + GStreamer 1.x plugin
(18:18:18) DEBUG: setenv()/putenv() are not thread-safe and should not be used after threads are created
(18:18:18) DEBUG: setenv()/putenv() are not thread-safe and should not be used after threads are created
(18:18:18) DEBUG: rm_plugins_enable(): + Benachrichtigung (mittels GNotification)
(18:18:18) DEBUG: fritzbox_load_journal(): called (113.7.21)
(18:18:18) DEBUG: Bootstrap: Querying all addresses
(18:18:18) DEBUG: Received RTM_NEWADDR
(18:18:18) DEBUG: Created SSDP client 0x0x5579368eddb0
(18:18:18) DEBUG: iface_name : lo
(18:18:18) DEBUG: host_ip : (null)
(18:18:18) DEBUG: server_id : Linux/5.4.0-65-generic UPnP/1.0 GSSDP/1.2.1
(18:18:18) DEBUG: network : 127.0.0.0
(18:18:18) DEBUG: host_addr : 0x0x55793692d6e0
(18:18:18) DEBUG: host_mask : 0x0x557936ccd130
(18:18:18) DEBUG: Received RTM_NEWADDR
(18:18:18) DEBUG: Created SSDP client 0x0x5579368edbd0
(18:18:18) DEBUG: iface_name : enp0s25
(18:18:18) DEBUG: host_ip : (null)
(18:18:18) DEBUG: server_id : Linux/5.4.0-65-generic UPnP/1.0 GSSDP/1.2.1
(18:18:18) DEBUG: network : 192.168.188.0
(18:18:18) DEBUG: host_addr : 0x0x557936cd0ee0
(18:18:18) DEBUG: host_mask : 0x0x557936ccd220
(18:18:18) DEBUG: GSocketClient: Starting new address enumeration
(18:18:18) DEBUG: GSocketClient: Starting new address enumeration
(18:18:18) DEBUG: GSocketClient: Address enumeration succeeded
(18:18:18) DEBUG: GSocketClient: Starting TCP connection attempt
(18:18:18) DEBUG: GSocketClient: Address enumeration succeeded
(18:18:18) DEBUG: GSocketClient: Starting TCP connection attempt
(18:18:18) DEBUG: GSocketClient: TCP connection successful
(18:18:18) DEBUG: GSocketClient: Starting application layer connection
(18:18:18) DEBUG: GSocketClient: Connection successful!
(18:18:18) DEBUG: GSocketClient: TCP connection successful
(18:18:18) DEBUG: GSocketClient: Starting application layer connection
(18:18:18) DEBUG: GSocketClient: Connection successful!
(18:18:18) DEBUG: rm_router_present(): Got active router
(18:18:18) DEBUG: rm_router_present(): Got active router
(18:18:19) DEBUG: firmware_tr64_journal_cb(): process journal (396)
(18:18:43) DEBUG: rm_faxserver_thread(): file: /home/bem/.var/app/org.tabos.roger/cache/rm/fax-IL0WX0 (42)
(18:18:43) DEBUG: rm_faxserver_thread(): Print job received on socket (/home/bem/.var/app/org.tabos.roger/cache/rm/fax-IL0WX0)
(18:18:43) DEBUG: convert_to_fax(): out_file: '/home/bem/.var/app/org.tabos.roger/cache/rm/fax-IL0WX0.tif'
(18:18:43) DEBUG: convert_to_fax(): 1. ret 0
(18:18:43) DEBUG: convert_to_fax(): 1.1 ret 0
(18:18:43) DEBUG: convert_to_fax(): 2. ret 0
(18:18:43) DEBUG: convert_to_fax(): final ret 0
(18:18:43) DEBUG: contact_search_init(): book 'FritzFon'
(18:18:49) DEBUG: fax_pickup_button_clicked_cb(): Dialing '05XXXXXXXXX3'
(18:18:49) DEBUG: capi_fax_dial(): Using 'Analog Fax' id
(18:18:49) DEBUG: capi_fax_send(): tiff: /home/bem/.var/app/org.tabos.roger/cache/rm/fax-IL0WX0.tif, modem: 3, ecm: off, controller: 4, src: 4328193, trg: 053149059113, ident: +49XXXXXX8193, header: Roger Router, anonymous: 0)
(18:18:49) DEBUG: REQ: CONNECT (4328193->053149059113)
(18:18:49) DEBUG: fax_pickup_button_clicked_cb(): connection 0x5579364a5920
(18:18:49) DEBUG: CNF: CAPI_CONNECT - (plci: 3588, info: 0)
(18:18:49) DEBUG: CAPI_INFO - SETUP ACK
(18:18:49) DEBUG: CAPI_INFO - PROGRESS INDICATOR (0x02)
(18:18:49) DEBUG: CAPI_INFO - In-band information available
(18:18:49) DEBUG: CAPI_INFO - CHANNEL IDENTIFICATION (0x03)
(18:18:49) DEBUG: CAPI_INFO - UNKNOWN INFO (0xc000)
(18:19:00) DEBUG: CAPI_INFO - ALERTING (Setup early...)
(18:19:00) DEBUG: CAPI_INFO - PROGRESS INDICATOR (0x02)
(18:19:00) DEBUG: CAPI_INFO - In-band information available
(18:19:00) DEBUG: CAPI_INFO - CALLED PARTY NUMBER
(18:19:00) DEBUG: CAPI_INFO - CHANNEL IDENTIFICATION (0x03)
(18:19:00) DEBUG: CAPI_INFO - UNKNOWN INFO (0xc000)
(18:19:05) DEBUG: IND: CAPI_CONNECT_ACTIVE - plci 3588
(18:19:05) DEBUG: RESP: CAPI_CONNECT_ACTIVE - plci 3588
(18:19:05) DEBUG: IND: CAPI_CONNECT_ACTIVE - connection: 1024, plci: 3588
(18:19:05) DEBUG: REQ: CONNECT_B3 - nplci 3588
(18:19:05) DEBUG: CNF: CAPI_CONNECT_B3
(18:19:05) DEBUG: IND: CAPI_CONNECT_B3_ACTIVE
(18:19:05) DEBUG: NCPI len: 1
(18:19:05) DEBUG: 00 <->
(18:19:05) DEBUG: Enable DTMF for PLCI 3588
(18:19:05) DEBUG: rm_object_emit_connection_changed(): Device 'CAPI' handles number '4328193'
(18:19:05) DEBUG: rm_profile_get_notification(): No notification set, using first one GNotification
(18:19:05) DEBUG: rm_notification_connection_changed_cb(): Outgoing
(18:19:05) DEBUG: rm_notification_connection_changed_cb(): type = 6, numbers is empty
(18:19:05) DEBUG: fax_connection_changed_cb(): connection 0x5579364a5920
(18:19:05) DEBUG: CNF: CAPI_FACILITY; Info: 0
(18:19:06) DEBUG: IND: CAPI_FACILITY
(18:19:06) DEBUG: IND: CAPI_FACILITY 1
(18:19:06) DEBUG: IND: CAPI_FACILITY
(18:19:06) DEBUG: IND: CAPI_FACILITY 1
(18:19:09) DEBUG: capi_fax_phase_handler_b(): Phase B handler (0x80) DIS
(18:19:09) DEBUG: capi_fax_phase_handler_b(): - bit rate 14400
(18:19:09) DEBUG: capi_fax_phase_handler_b(): - ecm off
(18:19:09) DEBUG: capi_fax_phase_handler_b(): - Remote side: 'FAX'
(18:19:09) DEBUG: capi_fax_phase_handler_b(): - pages_transferred 0
(18:19:21) DEBUG: capi_fax_phase_handler_e(): Phase E handler (0x12) Invalid response after sending a page
(18:19:22) DEBUG: fax_status_timer_cb(): Fax transfer failed
(18:19:22) DEBUG: rm_contact_find_by_number(): phone number type -1
(18:19:22) DEBUG: REQ: DISCONNECT_B3 - ncci 69124
(18:19:22) DEBUG: CNF: CAPI_DISCONNECT_B3
(18:19:22) DEBUG: IND: DISCONNECT_B3
(18:19:22) DEBUG: REQ: DISCONNECT - plci 3588
(18:19:22) DEBUG: IND: CAPI_DISCONNECT_B3 - connection: 1024, plci: 3588, ncci: 0
(18:19:22) DEBUG: CNF: CAPI_DISCONNECT
(18:19:25) DEBUG: IND: DISCONNECT - plci 3588
(18:19:25) DEBUG: RESP: DISCONNECT - plci 3588
(18:19:25) DEBUG: callmonitor_convert(): '01.02.21 18:19:06;CALL;0;5;4328193;053149059113;POTS;
'
(18:19:25) DEBUG: rm_object_emit_connection_changed(): Device 'CAPI' handles number '4328193'
(18:19:25) DEBUG: rm_object_emit_connection_changed(): Device 'Call Monitor' does not handle number '4328193'
(18:19:25) DEBUG: fritzbox_load_journal(): called (113.7.21)
(18:19:25) DEBUG: callmonitor_convert(): '01.02.21 18:19:06;CONNECT;0;5;053149059113;
'
(18:19:25) DEBUG: rm_object_emit_connection_changed(): Device 'Call Monitor' does not handle number '4328193'
(18:19:25) DEBUG: callmonitor_convert(): '01.02.21 18:19:25;DISCONNECT;0;20;
'
(18:19:25) DEBUG: rm_object_emit_connection_changed(): Device 'Call Monitor' does not handle number '4328193'
(18:19:26) DEBUG: rm_profile_get_notification(): No notification set, using first one GNotification
(18:19:26) DEBUG: rm_notification_connection_changed_cb(): Outgoing
(18:19:26) DEBUG: rm_notification_connection_changed_cb(): type = 14, numbers is empty
(18:19:26) DEBUG: fax_connection_changed_cb(): connection 0x5579364a5920
(18:19:26) DEBUG: fax_connection_changed_cb(): cleanup
(18:19:26) DEBUG: fax_status_timer_cb(): Fax transfer failed
(18:19:26) DEBUG: capi_fax_clean(): called
(18:19:26) DEBUG: firmware_tr64_journal_cb(): process journal (396)

[janbrummer]

The error message is send from the remote fax machine. You can try to alter your settings in Roger Router and play with ECM and service, but at the end fax through IP is always not 100% reliable.

[firewiremb]

Many thanks for your response!
I've already tried it with several fax machines. So that I can rule out problems on the recipient side. I've also tried all possible options. With ECM, without ECM, etc. I always get an error message from the recipient side.
I've read that a reduced bit rate might help. Is there a possibility in Roger Router to reduce this from 14400 to 9600? Maybe via a config file or something similar?

[janbrummer]

Actually there is, but the speed is auto negotiated between those partners. Anyway, you can give it a try. the hidden setting is called fax-bitrate in gsettings. A lower value for lower speeds.

[firewiremb]

Thank you again for your answer. Unfortunately, I cannot find the gsettings file. In which directory is it stored?

[janbrummer]

They are in ~/.var/app/org.tabos.roger/config/glib-2.0/settings/keyfile

[firewiremb]

Thank you for the information! Unfortunately, the changed bit rate does not eliminate the problem.

However, I have new information on the problem. As I wrote above, I tried faxing with several fax machines.
The behavior was the same for all receiving devices. In the meantime, the owner of one of the fax machines contacted me and asked me why I had sent him numerous test faxes.

Further tests have shown that the fax page reaches the recipient reliably, but that the Roger Router nevertheless reports "Fax transmission failed".

When the ECM is switched off, the debug log contains capi_fax_phase_handler_e (): Phase E handler (0x12) Invalid response after sending a page

and with activated ECM capi_fax_phase_handler_e (): Phase E handler (0x10) Invalid ECM response received from receiver

Is it possible that the response from the receiving fax machine to the Roger Router is merely incorrectly evaluated by the Roger Router?

My configuration is such that the Fritzbox 7490 hangs on an analog telephone connection over which the fax is sent. So I don't use VoIP.

Is there anyone who has the same problem with an identical configuration? Or is there someone who can send and receive over an analog phone line without any problems?

[janbrummer]

Are analog still a thing, i thought everything has moved to the digital world. But regarding your problem i'm afraid i can't help here. The actual work is done through spandsp, so those problems must be reported there.

[janbrummer]

Closing as not Roger Router.