Troubleshooting

Last modified by François Grisez on 2023/01/10 12:01

Fetch the operation logs

By default, all the operation logs are in the directory /var/opt/belledonne-communications/logs/flexisip on the machine that hosts Flexisip. This directory may be changed by the parameter global/log-directory.

There is a plain text log file for each Flexisip service :

ServiceLog name
SIP Proxyflexisip-proxy.log
Presence serverflexisip-presence.log
Conference server (Group chat server)flexisip-conference.log
Registration event serverflexisip-regevent.log

flexisip-proxy.log and flexisip-conference.log are enough for the great majority of problems.

Each log file is automatically rotated and compressed by logrotate script, so be careful to select the good rotation by checking the last modification time of the file.

How to read Flexisip's log files

Flexisp-proxy.log

Available information on proxy starting

The last starting may be found by the searching the last occurrence of:

2023-01-05 14:44:19:901 flexisip-message-Starting flexisip proxy-server version 2.2.0

 Here are some useful parts of the log on starting :

Content of /etc/hosts

2023-01-05 14:44:19:911 flexisip-debug-Read 127.0.0.1 localhost
2023-01-05 14:44:19:911 flexisip-debug-Read 127.0.0.1 localhost.localdomain
2023-01-05 14:44:19:911 flexisip-debug-Read 127.0.0.1 localhost4
2023-01-05 14:44:19:911 flexisip-debug-Read 127.0.0.1 localhost4.localdomain4
2023-01-05 14:44:19:911 flexisip-debug-Read ::1 localhost
2023-01-05 14:44:19:911 flexisip-debug-Read ::1 localhost.localdomain
2023-01-05 14:44:19:911 flexisip-debug-Read ::1 localhost6
2023-01-05 14:44:19:911 flexisip-debug-Read ::1 localhost6.localdomain6

Order of the Flexisip modules and message on their initialization

2023-01-05 14:44:19:912 flexisip-message-Creating module instance of [DoSProtection].
2023-01-05 14:44:19:912 flexisip-debug-BasicThreadPool [0xd42ce0]: init with 1 threads and queue size 1000
2023-01-05 14:44:19:912 flexisip-message-Creating module instance of [SanityChecker].
2023-01-05 14:44:19:912 flexisip-message-Creating module instance of [GarbageIn].
2023-01-05 14:44:19:912 flexisip-message-Creating module instance of [NatHelper].
2023-01-05 14:44:19:912 flexisip-message-Creating module instance of [Authentication].
2023-01-05 14:44:19:912 flexisip-message-Creating module instance of [Redirect].
2023-01-05 14:44:19:912 flexisip-message-Creating module instance of [RegEvent].
2023-01-05 14:44:19:912 flexisip-message-Creating module instance of [B2bua].
2023-01-05 14:44:19:912 flexisip-message-Creating module instance of [GatewayAdapter].
2023-01-05 14:44:19:912 flexisip-message-Creating module instance of [Presence].
2023-01-05 14:44:19:912 flexisip-message-Creating module instance of [Registrar].
2023-01-05 14:44:19:912 flexisip-message-Creating module instance of [StatisticsCollector].
2023-01-05 14:44:19:912 flexisip-message-Creating module instance of [ContactRouteInserter].
2023-01-05 14:44:19:912 flexisip-message-Creating module instance of [Router].
2023-01-05 14:44:19:912 flexisip-message-Creating module instance of [PushNotification].
2023-01-05 14:44:19:912 flexisip-message-Creating module instance of [LoadBalancer].
2023-01-05 14:44:19:912 flexisip-message-Creating module instance of [MediaRelay].
2023-01-05 14:44:19:912 flexisip-message-Creating module instance of [Transcoder].
[…]
2023-01-05 14:44:19:915 flexisip-message-Creating module instance of [Forward].

Version of Mediastreamer (SDK version)

2023-01-05 14:44:19:912 mediastreamer-message-Mediastreamer2 factory 5.2.0 (git: 5.2.6) initialized.

Number of CPU threads

2023-01-05 14:44:19:912 mediastreamer-message-CPU count set to 4

Other debug info on Mediastreamer library initialization

2023-01-05 14:44:19:912 mediastreamer-message-ms_factory_init() done: platform_tags=linux,x86,desktop
2023-01-05 14:44:19:912 mediastreamer-message-srtp init
2023-01-05 14:44:19:915 mediastreamer-message-Registering all soundcard handlers
2023-01-05 14:44:19:915 mediastreamer-message-Registering all webcam handlers
2023-01-05 14:44:19:915 mediastreamer-message-Webcam StaticImage: Static picture added
2023-01-05 14:44:19:915 mediastreamer-message-ms_factory_init_voip() done
2023-01-05 14:44:19:915 mediastreamer-message-Loading ms plugins from [/opt/belledonne-communications/lib64/mediastreamer/plugins]
2023-01-05 14:44:19:915 mediastreamer-message-Cannot open directory /opt/belledonne-communications/lib64/mediastreamer/plugins: No such file or directory

List of the network interfaces and their settings

2023-01-05 14:44:19:921 flexisip-debug-New network: Name: lo    Address: 127.0.0.1      Mask: 255.0.0.0
2023-01-05 14:44:19:921 flexisip-debug-New network: Name: ens192        Address: 51.255.123.123 Mask: 255.255.255.255
2023-01-05 14:44:19:921 flexisip-debug-New network: Name: lo    Address: ::1    Mask: ffff:ffff:ffff:ffff:ffff:ffff:ffff:ffff
2023-01-05 14:44:19:921 flexisip-debug-New network: Name: ens192        Address: 2001:41d0:403:2767::1234       Mask: ffff:ffff:ffff:ffff::
2023-01-05 14:44:19:922 flexisip-debug-New network: Name: ens192        Address: fe80::250:56ff:fe06:95ee%ens192        Mask: ffff:ffff:ffff:ffff::

List of the host aliases

List of the aliases that have been given by global/aliases parameter.

2023-01-05 14:44:19:923 flexisip-debug-List of host aliases:
2023-01-05 14:44:19:923 flexisip-debug-sip.linphone.org
2023-01-05 14:44:19:923 flexisip-debug-sip.linhome.org
2023-01-05 14:44:19:923 flexisip-debug-sip8.linhome.org

Backend used for the registrar database

See module::Registrar/db-implementation.

2023-01-05 14:44:19:923 flexisip-message-RegistrarDB implementation is REDIS
2023-01-05 14:44:19:923 flexisip-debug-Connecting to Redis server tcp://localhost:6379
2023-01-05 14:44:19:923 flexisip-debug-Creating main Redis connection
2023-01-05 14:44:19:924 flexisip-debug-Creating subscription Redis connection
2023-01-05 14:44:19:924 flexisip-debug-Authenticating to Redis server

Value of the internal transport

See cluster/internal-transport.

2023-01-05 14:44:19:924 flexisip-debug-Agent's preferred IP for internal routing find: v4: sip:10.0.0.24:5059;transport=tcp

Global TLS certificates/key location

2023-01-05 14:44:19:924 flexisip-debug-Main tls certs file [/etc/letsencrypt/live/sip.example.org/fullchain.pem], main private key file [/etc/letsencrypt/live/sip.example.org/privkey.pem], main CA file [].

List of listening addresses and ports (listening transports)

2023-01-05 14:44:20:109 flexisip-debug-Agent 's primaries are:
2023-01-05 14:44:20:109 flexisip-debug- sip:51.xxx.xxx.xxx:5060;transport=udp;maddr=51.xxx.xxx.xxx
2023-01-05 14:44:20:109 flexisip-debug- sip:51.xxx.xxx.xxx:5060;transport=tcp;maddr=51.xxx.xxx.xxx
2023-01-05 14:44:20:109 flexisip-debug- sip:[2001:xxxx:xxx:xxxx::1234]:5060;transport=udp;maddr=[2001:xxxx:xxx:xxxx::1234]
2023-01-05 14:44:20:109 flexisip-debug- sip:[2001:xxxx:xxx:xxxx::1234]:5060;transport=tcp;maddr=[2001:xxxx:xxx:xxxx::1234]
2023-01-05 14:44:20:109 flexisip-debug- sip:127.0.0.1:5060;transport=udp;maddr=127.0.0.1
2023-01-05 14:44:20:109 flexisip-debug- sip:127.0.0.1:5060;transport=tcp;maddr=127.0.0.1
2023-01-05 14:44:20:109 flexisip-debug- sip:[::1]:5060;transport=udp;maddr=[::1]
2023-01-05 14:44:20:109 flexisip-debug- sip:[::1]:5060;transport=tcp;maddr=[::1]
2023-01-05 14:44:20:109 flexisip-debug- sip:sip8.linphone.org:5061;transport=tls;maddr=[2001:xxxx:xxx:xxxx::1234]
2023-01-05 14:44:20:119 flexisip-debug- sip:sip8.linphone.org:5061;transport=tls;maddr=51.xxx.xxx.xxx
2023-01-05 14:44:20:132 flexisip-debug- sip:51.xxx.xxx.xxx:5228;transport=tcp;maddr=51.xxx.xxx.xxx
2023-01-05 14:44:20:132 flexisip-debug- sip:[2001:xxxx:xxx:xxxx::1234]:5228;transport=tcp;maddr=[2001:xxxx:xxx:xxxx::1234]
2023-01-05 14:44:20:132 flexisip-debug- sip:127.0.0.1:5228;transport=tcp;maddr=127.0.0.1
2023-01-05 14:44:20:132 flexisip-debug- sip:[::1]:5228;transport=tcp;maddr=[::1]
2023-01-05 14:44:20:132 flexisip-debug- sip:sip8.linphone.org:5223;transport=tls;maddr=[2001:xxxx:xxx:xxxx::1234]
2023-01-05 14:44:20:139 flexisip-debug- sip:sip8.linphone.org:5223;transport=tls;maddr=51.xxx.xxx.xxx
2023-01-05 14:44:20:152 flexisip-debug- sip:51.xxx.xxx.xxx:5059;transport=tcp;maddr=51.xxx.xxx.xxx

DoS Protection whitelist

See module::DoSProtection/white-list.

2023-01-05 14:44:20:160 flexisip-message-IP 127.0.0.1 and ::1 automatically added to DOS protection white list
2023-01-05 14:44:20:160 flexisip-message-Host 91.xxx.xxx.xxx is in DOS protection white list
2023-01-05 14:44:20:160 flexisip-message-Host 2001:xxxx:x:xxxx:: is in DOS protection white list

Trusted hosts while authentication

See module::Authentication/trusted-hosts.

2023-01-05 14:44:20:201 flexisip-message-Added presence server '127.0.0.1' to trusted hosts
2023-01-05 14:44:20:201 flexisip-message-IP [::1]:0 added to trusted hosts
2023-01-05 14:44:20:201 flexisip-message-IP [::ffff:5.xxx.xx.xxx]:0 added to trusted hosts

Domains that are authorized to operate with the proxy (after authentication)

See module::Authentication/auth-domains.

2023-01-05 14:44:20:202 flexisip-message-Found auth domain: sip.linphone.org
2023-01-05 14:44:20:202 flexisip-message-Found auth domain: sip.linhome.org

Push notification clients creation

Available information:

  • Directory where APNS client certificates are placed in;
  • Creation of each Apple client and the expiration date of the related APNS certificate;
  • Creation of each Android/Firebase client and the related ProjectID;
  • The TTL used for each Push Notification Request according the kind of event (call or instant message).
2023-01-05 14:44:47:124 flexisip-debug-Searching push notification client on dir [/etc/flexisip/apn]
2023-01-05 14:44:47:150 flexisip-debug-AppleClient[0x26583a0]: constructing AppleClient
2023-01-05 14:44:47:152 flexisip-debug-Certificate /etc/flexisip/apn/org.linphone.phone.dev.pem has a valid expiration: Jun 23 08:57:28 2023 GMT.
2023-01-05 14:44:47:152 flexisip-debug-Http2Client[0x2658a60]: constructing Http2Client with TlsConnection[0x2658ca0]
2023-01-05 14:44:47:152 flexisip-debug-Adding ios push notification client [org.linphone.phone.dev]
2023-01-05 14:44:47:152 flexisip-debug-AppleClient[0x199f290]: constructing AppleClient
2023-01-05 14:44:47:153 flexisip-debug-Certificate /etc/flexisip/apn/org.linphone.phone.prod.pem has a valid expiration: Jun 23 08:57:28 2023 GMT.
2023-01-05 14:44:47:153 flexisip-debug-Http2Client[0x199fa30]: constructing Http2Client with TlsConnection[0x199ca90]
2023-01-05 14:44:47:153 flexisip-debug-Adding ios push notification client [org.linphone.phone.prod]
2023-01-05 14:44:47:153 flexisip-debug-AppleClient[0x2653ad0]: constructing AppleClient
2023-01-05 14:44:47:153 flexisip-debug-Certificate /etc/flexisip/apn/org.linphone.phone.voip.dev.pem has a valid expiration: Jun 23 08:57:28 2023 GMT.
2023-01-05 14:44:47:153 flexisip-debug-Http2Client[0x2654240]: constructing Http2Client with TlsConnection[0x2654480]
2023-01-05 14:44:47:153 flexisip-debug-Adding ios push notification client [org.linphone.phone.voip.dev]
2023-01-05 14:44:47:153 flexisip-debug-AppleClient[0x1d91e80]: constructing AppleClient
2023-01-05 14:44:47:154 flexisip-debug-Certificate /etc/flexisip/apn/org.linphone.phone.voip.prod.pem has a valid expiration: Jun 23 08:57:28 2023 GMT.
2023-01-05 14:44:47:154 flexisip-debug-Http2Client[0x1d926d0]: constructing Http2Client with TlsConnection[0x1d92910]
2023-01-05 14:44:47:154 flexisip-debug-Adding ios push notification client [org.linphone.phone.voip.prod]
2023-01-05 14:44:47:208 flexisip-debug-FirebaseClient[0x2689540]: constructing FirebaseClient
2023-01-05 14:44:47:208 flexisip-debug-Http2Client[0x2689300]: constructing Http2Client with TlsConnection[0x118a700]
2023-01-05 14:44:47:208 flexisip-debug-Adding firebase push notification client [92xxxxxxxxxx]
2023-01-05 14:44:47:209 flexisip-debug-PushNotification module loaded. Push ttl for calls is 50 seconds, and for IM 604800 seconds.

Debug the flow of a request

Each incoming/outgoing SIP message are systematically logged but without their body (excepted for call session INVITEs). So, you can easily follow the flow of a given request by searching for its Call-ID. For instance,

Received message:

2023-01-09 14:03:14:116 flexisip-debug-tport_wakeup_pri(0xe77750): events IN
2023-01-09 14:03:14:116 flexisip-debug-tport_recv_event(0xe77750)
2023-01-09 14:03:14:116 flexisip-debug-tport_recv_iovec(0xe77750) msg 0x2e52390 from (udp/51.xxx.xxx.xxx:5060) has 1841 bytes, veclen = 1
2023-01-09 14:03:14:116 flexisip-debug-tport_deliver(0xe77750): msg 0x2e52390 (1841 bytes) from udp/77.xxx.xx.xx:5060 next=(nil)
2023-01-09 14:03:14:116 flexisip-debug-nta: received INVITE sip:alice@sip.linphone.org:5060 SIP/2.0 (CSeq 21)
2023-01-09 14:03:14:116 flexisip-debug-nta: Via check: received=77.xxx.xx.xx
2023-01-09 14:03:14:116 flexisip-debug-nta: INVITE (21) to message callback
2023-01-09 14:03:14:116 flexisip-debug-New SipEvent 0x169b7630 - msg 0x2e52390
2023-01-09 14:03:14:116 flexisip-debug-Receiving new Request SIP message INVITE from sip:alice@sip.linphone.org :
INVITE sip:bob@sip.linphone.org:5060 SIP/2.0
Via: SIP/2.0/UDP 192.xxx.x.xxx:5060;branch=z9hG4bK.awUT5hrJB;rport=1024;received=77.xxx.xx.xx
From: <sip:alice@sip.linphone.org>;tag=T2WPeSsHv
To: sip:bob@sip.linphone.org
CSeq: 21 INVITE
Call-ID: FGwjp7bRfw
Max-Forwards: 70
Supported: replaces, outbound
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO, UPDATE
Content-Type: application/sdp
Content-Length: 920
Contact: <sip:alice@77.xxx.xx.xx:1024>;+sip.instance="<urn:uuid:xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxx>"
User-Agent: Unknown (belle-sip/1.4.2)
Proxy-Authorization: Digest realm="sip.linphone.org", nonce="xxxxxx", algorithm=MD5, opaque="+GNywA==", username="xxxxxx", uri="sip:alice@sip.linphone.org:5060", response="xxxxxx", cnonce="xxxxxx", nc=00000001, qop=auth

[…]

Forwarded message:

2023-01-09 14:03:14:118 flexisip-debug-Sending Request SIP message to sip:bob@77.xxx.xx.xx:42546;transport=tls
INVITE sip:bob@77.129.18.79:42546;transport=tls SIP/2.0
Record-Route: <sips:sip8.linphone.org:5223;lr>
Record-Route: <sip:51.xxx.xxx.xxx:5060;lr>
Via: SIP/2.0/UDP 192.xxx.x.xxx:5060;branch=z9hG4bK.awUT5hrJB;rport=1024;received=77.xxx.xx.xx
Max-Forwards: 69
From: <sip:alice@sip.linphone.org>;tag=T2WPeSsHv
To: sip:bob@sip.linphone.org
Call-ID: FGwjp7bRfw
CSeq: 21 INVITE
Contact: <sip:alice@77.xxx.xx.xx:1024>;+sip.instance="<urn:uuid:xxxxxxxx-xxxx-xxxx-xxxxxxxxxxxx>"
User-Agent: Unknown (belle-sip/1.4.2)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO, UPDATE
Supported: replaces, outbound
Content-Type: application/sdp
Content-Length: 940

[…]

2023-01-09 14:03:14:118 flexisip-debug-Message is sent through an outgoing transaction.
2023-01-09 14:03:14:118 flexisip-debug-tport_tsend(0x1d4cd2a0) tpn = tls/77.xxx.xx.xx:42546
2023-01-09 14:03:14:118 flexisip-debug-tport_tls_writevec: vec 0x757c9b0 0x193b3c0 844 (844)
2023-01-09 14:03:14:118 flexisip-debug-tport_tls_writevec: vec 0x757c9b0 0xd14ef40 940 (940)
2023-01-09 14:03:14:118 flexisip-debug-tport_vsend returned 1784

While an incoming request is processed by Flexisip, it goes through a chain of modules that may do the following action on the request:

  • Add/remove/alter the headers of the message;
  • Pass the request to the next module;
  • Suspend the request, which cause the Flexisip to process another incoming request;
  • Reply to the request with a terminal SIP response; the request won't go through the next modules.

Flexisip suspends a request when it is waiting for the result of an asynchronous operation (for example the response of a SQL request) to find out which action to do on the request.

Example of request processing:

INVITE sip:bob@sip.linphone.org:5060 SIP/2.0
Via: SIP/2.0/UDP 192.xxx.x.xxx:5060;branch=z9hG4bK.awUT5hrJB;rport=1024;received=77.xxx.xx.xx
From: <sip:alice@sip.linphone.org>;tag=T2WPeSsHv
To: sip:bob@sip.linphone.org
CSeq: 21 INVITE
Call-ID: FGwjp7bRfw
Max-Forwards: 70
Supported: replaces, outbound
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO, UPDATE
Content-Type: application/sdp
Content-Length: 920
Contact: <sip:alice@77.xxx.xx.xx:1024>;+sip.instance="<urn:uuid:xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxx>"
User-Agent: Unknown (belle-sip/1.4.2)
Proxy-Authorization: Digest realm="sip.linphone.org", nonce="xxxxxx", algorithm=MD5, opaque="+GNywA==", username="xxxxxx", uri="sip:alice@sip.linphone.org:5060", response="xxxxxx", cnonce="xxxxxx", nc=00000001, qop=auth

[…]

2023-01-09 14:03:14:116 flexisip-debug-Invoking onRequest() on module DoSProtection
2023-01-09 14:03:14:116 flexisip-debug-Invoking onRequest() on module SanityChecker
2023-01-09 14:03:14:116 flexisip-debug-Skipping onRequest() on module GarbageIn
2023-01-09 14:03:14:116 flexisip-debug-Invoking onRequest() on module NatHelper
2023-01-09 14:03:14:116 flexisip-debug-Record route added.
2023-01-09 14:03:14:116 flexisip-debug-Invoking onRequest() on module Authentication
2023-01-09 14:03:14:116 flexisip-debug-New IncomingTransaction 0x17eace80
2023-01-09 14:03:14:116 flexisip-debug-nta_incoming_create: created incoming transaction 0x159f5900
2023-01-09 14:03:14:116 flexisip-debug-start digest authentication
2023-01-09 14:03:14:116 flexisip-debug-New FlexisipAuthStatus [0x8ad0e20]
2023-01-09 14:03:14:116 flexisip-debug-AuthStatus[0x8ad0e20]: 'sip.linphone.org' will be used as realm
2023-01-09 14:03:14:116 flexisip-debug-AuthStatus[0x8ad0e20]: searching for auth digest response for this proxy
2023-01-09 14:03:14:116 flexisip-debug-auth_digest_response_get: 12
2023-01-09 14:03:14:116 flexisip-debug-Examining auth digest response alice sip.linphone.org
2023-01-09 14:03:14:116 flexisip-debug-Expected realm found : sip.linphone.org
2023-01-09 14:03:14:116 flexisip-debug-auth_digest_response_get: 12
2023-01-09 14:03:14:116 flexisip-debug-AuthStatus[0x8ad0e20]: checking auth digest response for realm 'sip.linphone.org'
2023-01-09 14:03:14:116 flexisip-debug-Updating nonce Eo9m5wAAAAAnQPYOAACo/uw9zBsAAAAA with nc=1
2023-01-09 14:03:14:116 flexisip-debug-Suspend SipEvent 0x169b7630
2023-01-09 14:03:14:116 flexisip-debug-

==============================================================================================================

We see here that the request go through DoSProtection, SanityChecker, NetHelper and is suspended at the end of Authentication. The equal line means that Flexisip is changing context and is probably processing another request.

The processing of this request is resumed later in the log and suspended again while entering in the Router module:

==============================================================================================================

2023-01-09 14:03:14:116 flexisip-debug-AuthStatus[0x8ad0e20]: password found for 'alice@sip.linphone.org', algorithms={ 'MD5', 'SHA-256' }
2023-01-09 14:03:14:116 flexisip-debug-A2 = MD5(INVITE:sip:alice@sip.linphone.org:5060)
2023-01-09 14:03:14:116 flexisip-debug-computeDigestResponse(): xxxxxx = MD5(xxxxxx:xxxxxx:00000001:xxxxxx:auth:xxxxxx) (qop=auth)
2023-01-09 14:03:14:116 flexisip-debug-AuthStatus[0x8ad0e20]: successful authentication
2023-01-09 14:03:14:116 flexisip-debug-auth_digest_response_get: 12
2023-01-09 14:03:14:116 flexisip-debug-Examining auth digest response alice sip.linphone.org
2023-01-09 14:03:14:116 flexisip-debug-Expected realm found : sip.linphone.org
2023-01-09 14:03:14:116 flexisip-debug-Inject request SIP event [0x169b7630] after Authentication:
INVITE sip:alice@sip.linphone.org:5060 SIP/2.0
Via: SIP/2.0/UDP 192.xxx.x.xxx:5060;branch=z9hG4bK.awUT5hrJB;rport=1024;received=77.xxx.xx.xx
From: <sip:alice@sip.linphone.org>;tag=T2WPeSsHv
To: sip:bob@sip.linphone.org
CSeq: 21 INVITE
Call-ID: FGwjp7bRfw
Max-Forwards: 70
Supported: replaces, outbound
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO, UPDATE
Content-Type: application/sdp
Content-Length: 920
Contact: <sip:alice@77.xxx.xx.xx:1024>;+sip.instance="<urn:uuid:xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxx>"
User-Agent: Unknown (belle-sip/1.4.2)
Record-Route: <sip:51.xxx.xxx.xxx:5060;lr>

[…]

2023-01-09 14:03:14:116 flexisip-debug-Restart SipEvent 0x169b7630
2023-01-09 14:03:14:116 flexisip-debug-Skipping onRequest() on module Redirect
2023-01-09 14:03:14:116 flexisip-debug-Skipping onRequest() on module RegEvent
2023-01-09 14:03:14:116 flexisip-debug-Skipping onRequest() on module B2bua
2023-01-09 14:03:14:116 flexisip-debug-Skipping onRequest() on module GatewayAdapter
2023-01-09 14:03:14:116 flexisip-debug-Skipping onRequest() on module Presence
2023-01-09 14:03:14:116 flexisip-debug-Invoking onRequest() on module Registrar
2023-01-09 14:03:14:116 flexisip-debug-Skipping onRequest() on module StatisticsCollector
2023-01-09 14:03:14:116 flexisip-debug-Skipping onRequest() on module ContactRouteInserter
2023-01-09 14:03:14:116 flexisip-debug-Invoking onRequest() on module Router
2023-01-09 14:03:14:116 flexisip-debug-Fetch for url sip:bob@sip.linphone.org:5060.
2023-01-09 14:03:14:116 flexisip-debug-Replying Request SIP message: 100 Trying
2023-01-09 14:03:14:116 flexisip-debug-tport_tsend(0xe77750) tpn = UDP/77.xxx.xx.xx:1024
2023-01-09 14:03:14:116 flexisip-debug-tport_resolve addrinfo = 77.xxx.xx.xx:1024
2023-01-09 14:03:14:116 flexisip-debug-tport_by_addrinfo(0xe77750): not found by name UDP/77.xxx.xx.xx:1024
2023-01-09 14:03:14:116 flexisip-debug-tport_vsend returned 381
2023-01-09 14:03:14:116 flexisip-debug-nta: sent 100 Trying for INVITE (21)
2023-01-09 14:03:14:116 flexisip-debug-Suspend SipEvent 0x169b7630
2023-01-09 14:03:14:116 flexisip-debug-Fetching fs:bob@sip.linphone.org [0]
2023-01-09 14:03:14:116 flexisip-debug-

==============================================================================================================

Requests are finally forwarded while entering the Forward module, which is the last one in the chain.

Flexisip-conference.log

The SIP message flow may be easily followed by searching for the Call-ID of the message in the log.

Common issues

Push notifications not received by a SIP client

1. Check whether a Push Notification Request has been actually sent by the proxy

Use the Call-ID and the UUID of the recipient user agent to find the creation of the PNR.

Android/Firebase PNR creation:

2023-01-10 10:02:33:054 flexisip-debug-Firebase request creation 0xbf4d680 payload is :
{
        "to":"xxxxxxxxxx",
        "time_to_live": 50,
        "priority":"high",
        "data":{
                "uuid":"<urn:uuid:xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxx>",
                "from-uri":"sip:alice@sip.example.org",
                "display-name":"Alice",
                "call-id":"11-11-72CD0325-63BD29A900008351-D51D0700",
                "sip-from":"Alice",
                "loc-key":"",
                "loc-args":"Alice",
                "send-time":"2023-01-10 09:02:33"
        }
}

Apple PNR creation:

2023-01-10 10:03:10:520 flexisip-debug-Apple PNR 0x3f72f30 payload is :
{
        "aps": {
                "alert": {
                        "loc-key": "IM_MSG",
                        "loc-args": ["sip:alice@sip.linphone.org"]
                },
                "sound": "msg.caf",
                "mutable-content": 1,
                "badge": 1
        },
        "from-uri": "sip:alice@sip.example.org",
        "display-name": "",
        "call-id": "aOcJ3ckPh4",
        "pn_ttl": 604800,
        "uuid": "<urn:uuid:xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxx>",
        "send-time": "2023-01-10 09:03:10",
        "chat-room-addr": "",
        "customPayload": {}
}

Next, follow the state of the PNR by searching for its pointer, until you find this log:

2023-01-10 10:03:11:149 flexisip-debug-Request[0x3f72f30]: switching state from InProgress -> Successful

If the final state is “Successful”, the PNR has successfully been sent and accepted by the Push Notification Server. So, the problem is located on client side.

If the final state is “Failed”, the PNR sending has failed. You should scroll a little back to examine the body of the HTTP/2 response to know the reason of the failure.

Instance of failing response to Apple PNR:

2023-01-10 10:04:33:472 flexisip-debug-Http2Client[0x2658a60][1]: response received for HttpRequest[0x1e558ec8]:
HttpMessage :
    HttpMessage header :
:status = 410
apns-id = 9C1DF5E0-2C57-1A2A-C33B-876FE85A1E80

    HttpMessage body :
{"reason":"Unregistered","timestamp":1669987414400}
2023-01-10 10:04:33:472 flexisip-debug-Request[0x1e558ea0]: switching state from InProgress -> Failed

2. iOS client: check the validity of the APNS client certificates

When you follow the PNR pointer, you may find this error message just after the request creation:

2023-01-10 11:02:37:714 flexisip-error-No push notification client available for push notification request : 0x26925670

That means no PushClient has been created for the given “apns-topic”.

Get the “apns-topic“ in the HTTP/2 header just above the error message, org.example.myapp in this example:

2023-01-10 11:02:37:714 flexisip-debug-Apple PNR  0x26925670 https headers are :
:method = POST
:scheme = https
:path = /3/device/8796xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx
apns-expiration = 1673949757
apns-topic = org.example.myapp
apns-push-type = alert
apns-priority = 10

2023-01-10 11:02:37:714 flexisip-error-No push notification client available for push notification request : 0x26925670

Then, check the push client creation part on flexisip-proxy starting (see Push notification clients creation above). If the apns-topic is not present, that means no certificate for this topic is present in /etc/flexisip/apns, you should check the expiration date otherwise.