I contacted the asterisk user list to
see if they had any clue why linphone and asterisk were not
playing nicely with BLF and they pointed out that linphone seems
to be misusing the CSeq field, it is reusing old CSeq numbers,
which perturbs asterisk.
Anyway, here are the log messages,
showing that the sequence numbers are reset back to 20 just after
that:
message: 2020-03-23 16:28:52:756
channel [0x559e9e6fb9c0]: message sent to
[UDP://masked.masked.com:5060], size: [701] bytes
SUBSCRIBE
sip:address@hidden SIP/2.0
Via: SIP/2.0/UDP 10.27.128.3:5060;branch=z9hG4bK.hKKvVZmBM;rport
From:
<sip:address@hidden>;tag=H2AjtX90b
To:
sip:address@hidden
CSeq: 21 SUBSCRIBE
Call-ID: MBSfHKMXWt
Max-Forwards: 70
Supported: replaces, outbound
Event: presence
Expires: 600
Accept: application/pidf+xml
Contact:
<sip:john@10.27.128.3;transport=udp>;+sip.instance="<urn:uuid:abcdf51a-82e0-49b9-a8ab-2461011f25ec>"
User-Agent: Linphone/3.12.0 (belle-sip/1.6.3)
Authorization: Digest realm="asterisk", nonce="668f417b",
algorithm=MD5, username="john",
uri=
"sip:address@hidden",
response="aba753cbd5b96e186546d7aa61fbde09"
message: 2020-03-23 16:28:52:909 channel [0x559e9e759d60]:
received [509] new bytes from [UDP://::ffff:10.27.128.1:5060]:
SIP/2.0 200 OK
Via: SIP/2.0/UDP
10.27.128.3:5060;branch=z9hG4bK.hKKvVZmBM;received=10.27.128.3;rport=5060
From:
<sip:address@hidden>;tag=H2AjtX90b
To:
sip:address@hidden;tag=as4c653bef
Call-ID: MBSfHKMXWt
CSeq: 21 SUBSCRIBE
Server: Asterisk PBX 13.14.1~dfsg-2+deb9u4
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE,
NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Expires: 600
Contact:
<sip:jacques@10.27.128.1:5060>;expires=600
Content-Length: 0
message: 2020-03-23 16:28:52:912 channel [0x559e9e759d60] [509]
bytes parsed
message: 2020-03-23 16:28:52:913 channel message ready
message: 2020-03-23 16:28:52:913 message is response
message: 2020-03-23 16:28:52:913 learn_public_ip_port
message: 2020-03-23 16:28:52:913 set_public_ip_port
(0x559e9e759d60, 10.27.128.3, 5060)
message: 2020-03-23 16:28:52:913 Found transaction matching
response.
message: 2020-03-23 16:28:52:913 Changing [client] [SUBSCRIBE]
transaction [0x559e9e6f8770], from state [TRYING] to [COMPLETED]
message: 2020-03-23 16:28:52:939 channel [0x559e9e759d60]:
received [976] new bytes from [UDP://::ffff:10.27.128.1:5060]:
NOTIFY
sip:john@10.27.128.3;transport=udp SIP/2.0
Via: SIP/2.0/UDP 10.27.128.1:5060;branch=z9hG4bK5dcdab5e;rport
Max-Forwards: 70
From:
sip:address@hidden;tag=as4c653bef
To:
<sip:address@hidden>;tag=H2AjtX90b
Contact:
<sip:jacques@10.27.128.1:5060>
Call-ID: MBSfHKMXWt
CSeq: 102 NOTIFY
User-Agent: Asterisk PBX 13.14.1~dfsg-2+deb9u4
Subscription-State: active
Event: presence
Content-Type: application/pidf+xml
Content-Length: 503
<?xml version="1.0" encoding="ISO-8859-1"?>
<presence xmlns="urn:ietf:params:xml:ns:pidf"
xmlns:pp="urn:ietf:params:xml:ns:pidf:person"
xmlns:es="urn:ietf:params:xml:ns:pidf:rpid:status:rpid-status"
xmlns:ep="urn:ietf:params:xml:ns:pidf:rpid:rpid-person"
entity=
"sip:address@hidden">
<pp:person><status>
</status></pp:person>
<note>Ready</note>
<tuple id="jacques">
<contact
priority="1">
sip:address@hidden</contact>
<status><basic>open</basic></status>
</tuple>
</presence>
message: 2020-03-23 16:28:52:941 channel [0x559e9e759d60] [473]
bytes parsed
message: 2020-03-23 16:28:52:941 fix incoming via
message: 2020-03-23 16:28:52:941 channel [0x559e9e759d60] read
[503] bytes of body from [::ffff:10.27.128.1:5060]
message: 2020-03-23 16:28:52:941 Changing [server] [NOTIFY]
transaction [0x559e9e802400], from state [INIT] to [TRYING]
message: 2020-03-23 16:28:52:941 We are notified that
[
sip:address@hidden] has presence [open]
message: 2020-03-23 16:28:52:941 Linphone core [0x559e9e514570]
notified [notify_presence_received]
message: 2020-03-23 16:28:52:941 Changing [server] [NOTIFY]
transaction [0x559e9e802400], from state [TRYING] to [COMPLETED]
message: 2020-03-23 16:28:52:942 channel [0x559e9e759d60]: message
sent to [UDP://::ffff:10.27.128.1:5060], size: [309] bytes
SIP/2.0 200 Ok
Via: SIP/2.0/UDP 10.27.128.1:5060;branch=z9hG4bK5dcdab5e;rport
From:
<sip:address@hidden>;tag=as4c653bef
To:
<sip:address@hidden>;tag=H2AjtX90b
Call-ID: MBSfHKMXWt
CSeq: 102 NOTIFY
User-Agent: Linphone/3.12.0 (belle-sip/1.6.3)
Supported: replaces, outbound
message: 2020-03-23 16:37:52:932 Dialog [0x559e9e410d00]: now
updated by transaction [0x559e9e7d9140].
message: 2020-03-23 16:37:52:932
belle_sip_dialog_schedule_expiration() dialog=0x559e9e410d00
expires_value=600
message: 2020-03-23 16:37:52:932 Changing [client] [SUBSCRIBE]
transaction [0x559e9e7d9140], from state [INIT] to [TRYING]
message: 2020-03-23 16:37:52:933 channel [0x559e9e6fb9c0]: message
sent to [UDP://masked.masked.com:5060], size: [708] bytes
SUBSCRIBE
sip:jacques@10.27.128.1:5060 SIP/2.0
Via: SIP/2.0/UDP 10.27.128.3:5060;branch=z9hG4bK.CBFSYa5m5;rport
From:
<sip:address@hidden>;tag=H2AjtX90b
To:
<sip:address@hidden>;tag=as4c653bef
CSeq: 22 SUBSCRIBE
Call-ID: MBSfHKMXWt
Max-Forwards: 70
Supported: replaces, outbound
Event: presence
Expires: 600
Accept: application/pidf+xml
Contact:
<sip:john@10.27.128.3;transport=udp>;+sip.instance="<urn:uuid:abcdf51a-82e0-49b9-a8ab-2461011f25ec>"
User-Agent: Linphone/3.12.0 (belle-sip/1.6.3)
Authorization: Digest realm="asterisk", nonce="668f417b",
algorithm=MD5, username="john",
uri=
"sip:jacques@10.27.128.1:5060",
response="d30126abaee21f53462faae1e2220848"
message: 2020-03-23 16:37:52:933 channel [0x559e9e6fb9c0]: keep
alive sent to [UDP://masked.masked.com:5060]
message: 2020-03-23 16:37:52:933 channel [0x559e9e759d60]: keep
alive sent to [UDP://::ffff:10.27.128.1:5060]
message: 2020-03-23 16:37:52:962 channel [0x559e9e759d60]:
received [542] new bytes from [UDP://::ffff:10.27.128.1:5060]:
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP
10.27.128.3:5060;branch=z9hG4bK.CBFSYa5m5;received=10.27.128.3;rport=5060
From:
<sip:address@hidden>;tag=H2AjtX90b
To:
<sip:address@hidden>;tag=as4c653bef
Call-ID: MBSfHKMXWt
CSeq: 22 SUBSCRIBE
Server: Asterisk PBX 13.14.1~dfsg-2+deb9u4
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE,
NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm="asterisk",
nonce="00cc170d", stale=true
Content-Length: 0
message: 2020-03-23 16:37:52:966 channel [0x559e9e759d60] [542]
bytes parsed
message: 2020-03-23 16:37:52:966 channel message ready
message: 2020-03-23 16:37:52:966 message is response
message: 2020-03-23 16:37:52:966 learn_public_ip_port
message: 2020-03-23 16:37:52:966 set_public_ip_port
(0x559e9e759d60, 10.27.128.3, 5060)
message: 2020-03-23 16:37:52:966 Found transaction matching
response.
message: 2020-03-23 16:37:52:966 Changing [client] [SUBSCRIBE]
transaction [0x559e9e7d9140], from state [TRYING] to [COMPLETED]
message: 2020-03-23 16:37:52:966 Dialog [0x559e9e410d00]: now
updated by transaction [0x559e9e7d9140].
message: 2020-03-23 16:37:52:966
belle_sip_dialog_schedule_expiration() dialog=0x559e9e410d00
expires_value=600
message: 2020-03-23 16:37:52:966 Dialog [0x559e9e410d00] deleted
(is_expired=0)
error: 2020-03-23 16:37:52:966 Unexpected dialog state
[BELLE_SIP_DIALOG_TERMINATED] for dialog [0x559e9e410d00],
cannot refresh [SUBSCRIBE]
message: 2020-03-23 16:37:52:966 The SUBSCRIBE dialog no
longer works. Let's restart a new one.
message: 2020-03-23 16:37:52:966 Refresher [0x559e9e860f00]
stopped.
message: 2020-03-23 16:37:52:966 op [0x559e9e607350] :
set_or_update_dialog() current=[0x559e9e410d00] new=[(nil)]
message: 2020-03-23 16:37:52:966 Skipping top route of initial
route-set because same as request-uri.
message: 2020-03-23 16:37:52:966 Transaction [0x559e9e6f8770]
deleted
message: 2020-03-23 16:37:52:966 Changing [client] [SUBSCRIBE]
transaction [0x559e9e8312b0], from state [INIT] to [TRYING]
message: 2020-03-23 16:37:52:966 channel [0x559e9e6fb9c0]: message
sent to [UDP://masked.masked.com:5060], size: [523] bytes
SUBSCRIBE
sip:address@hidden SIP/2.0
Via: SIP/2.0/UDP 10.27.128.3:5060;branch=z9hG4bK.UiCAWLRbN;rport
From:
<sip:address@hidden>;tag=duI8a53B2
To:
sip:address@hidden
CSeq: 20 SUBSCRIBE
<<<<<<<<<<<<<<<<<
SEQUENCE RESTART!
Call-ID: MBSfHKMXWt
Max-Forwards: 70
Supported: replaces, outbound
Event: presence
Expires: 600
Accept: application/pidf+xml
Contact:
<sip:john@10.27.128.3;transport=udp>;+sip.instance="<urn:uuid:abcdf51a-82e0-49b9-a8ab-2461011f25ec>"
User-Agent: Linphone/3.12.0 (belle-sip/1.6.3)
message: 2020-03-23 16:37:52:966 Refresher [0x559e9e860f00]
stopped.
message: 2020-03-23 16:37:52:993 channel [0x559e9e759d60]:
received [528] new bytes from [UDP://::ffff:10.27.128.1:5060]:
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP
10.27.128.3:5060;branch=z9hG4bK.UiCAWLRbN;received=10.27.128.3;rport=5060
From:
<sip:address@hidden>;tag=duI8a53B2
To:
sip:address@hidden;tag=as09aae36f
Call-ID: MBSfHKMXWt
CSeq: 20 SUBSCRIBE
Server: Asterisk PBX 13.14.1~dfsg-2+deb9u4
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE,
NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm="asterisk",
nonce="5eb7d3dd"
Content-Length: 0
message: 2020-03-23 16:37:52:997 channel [0x559e9e759d60] [528]
bytes parsed
message: 2020-03-23 16:37:52:997 channel message ready
message: 2020-03-23 16:37:52:997 message is response
message: 2020-03-23 16:37:52:997 learn_public_ip_port
message: 2020-03-23 16:37:52:997 set_public_ip_port
(0x559e9e759d60, 10.27.128.3, 5060)
message: 2020-03-23 16:37:52:997 Found transaction matching
response.
message: 2020-03-23 16:37:52:997 Changing [client] [SUBSCRIBE]
transaction [0x559e9e8312b0], from state [TRYING] to [COMPLETED]
message: 2020-03-23 16:37:52:997 Transaction [0x559e9e5332f0]
deleted
message: 2020-03-23 16:37:52:997 linphone_core_find_auth_info():
returning auth info username=john, realm=asterisk
message: 2020-03-23 16:37:52:997 Auth info found for [john] realm
[asterisk]
message: 2020-03-23 16:37:52:997 Changing [client] [SUBSCRIBE]
transaction [0x559e9e8cfc30], from state [INIT] to [TRYING]
message: 2020-03-23 16:37:52:997 channel [0x559e9e6fb9c0]: message
sent to [UDP://masked.masked.com:5060], size: [701] bytes
SUBSCRIBE
sip:address@hidden SIP/2.0
Via: SIP/2.0/UDP 10.27.128.3:5060;branch=z9hG4bK.imZbILarH;rport
From:
<sip:address@hidden>;tag=duI8a53B2
To:
sip:address@hidden
CSeq: 21 SUBSCRIBE
Call-ID: MBSfHKMXWt
Max-Forwards: 70
Supported: replaces, outbound
Event: presence
Expires: 600
Accept: application/pidf+xml
Contact:
<sip:john@10.27.128.3;transport=udp>;+sip.instance="<urn:uuid:abcdf51a-82e0-49b9-a8ab-2461011f25ec>"
User-Agent: Linphone/3.12.0 (belle-sip/1.6.3)
Authorization: Digest realm="asterisk", nonce="5eb7d3dd",
algorithm=MD5, username="john",
uri=
"sip:address@hidden",
response="33492f9ff078775c22bff5c529c5c694"
message: 2020-03-23 16:37:53:024 channel [0x559e9e759d60]:
received [452] new bytes from [UDP://::ffff:10.27.128.1:5060]:
SIP/2.0 500 Server error
Via: SIP/2.0/UDP
10.27.128.3:5060;branch=z9hG4bK.imZbILarH;received=10.27.128.3;rport=5060
From:
<sip:address@hidden>;tag=duI8a53B2
To:
sip:address@hidden;tag=as4c653bef
Call-ID: MBSfHKMXWt
CSeq: 21 SUBSCRIBE
Server: Asterisk PBX 13.14.1~dfsg-2+deb9u4
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE,
NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0