Problem is solved.

The problem was in wrong regeneration of headers in ACK requests (uac restore_mode parameter).
This parameter helps to modify From/To headers in all sequential requests and replies in the same way as it has been modified in initial invite.

The uac from/to replacement relies that parties keep the same from/to headers content.
The mechanism to replace A with B is to combine both and get the key X which is added in the record-route as parameter.
Then practically from A and X results B and from B and X results A. It's doing XOR over base64-encoded values.

And when endpoint or kamailio changes the mid dialog From or To URI, then XOR against the key produces wrong values.


So the solution was to change this:
modparam("uac","restore_mode","auto")
modparam("uac","restore_dlg",1)

To this one:
modparam("uac","restore_mode","none")
modparam("uac","restore_dlg",0)

This case doesn't mean that uac module works improperly, of course no.
This means, that this options can only be used in topologies that can admit such behavior.
In our case, kamailio changes $fU to internal numbers (before to send it to an internal agent) for consistent callerid presentation.

So be careful while using such options in your topologies.




2017-11-16 15:42 GMT+02:00 Donat Zenichev <donat.zenichev@gmail.com>:
Hi Daniel.
We are using now kamailio 4.4.6
"the latest release series should have a safety check.." does it mean stable 5.0.4 ?
Well it is a reasonable advice I think, we haven't tried this way, yet.

I thought about using uac + dialog module together, but this entails a lot of changes in common logic.

For that moment looks like disabling the restore_mode and restore_dlg parameters solved the problem.
So that, it is enough for me to keep calm. But further, I want to make an effort to turn on dialog/uac modules together.

Thanks for your answers.
I will continue this topic as soon as I will start to work with it.

>Hello,
>
>it would be useful to know also the version of kamailio that is run
>there. The latest release series should have a safety check in order to
>prevent setting an invalid restored From/To URI.
>
>On the other hand, if the UA doesn't preserve the From/To, then it
>doesn't require to be unchanged, so the update (without auto restore) of
>the From/To can be done only for initial INVITE, when UA takes the
>caller/callee ids. For requests within the dialog, these headers can be
>left unchanged or changed to something like anonymous at anonymous.invalid
>
>The last option here, which is the safest, is to use dialog module
>together with uac, so uac module stores the From/To values inside the
>dialog and restores them from there, instead of relying on
>record-routing and the masking algorithm for values.
>
>Cheers,
>Daniel
>
>
>>On 14.11.17 08:04, Julia Boudniatsky wrote:
>> Hello,
>>
>> It looks like headers "From" in initial INVITE and received message
>> are different.
>>
>> For example:
>>  in INVITE : <sip:useragent7122 at kamailio_address:5068>>
>>  in received message : <sip:useragent7122 at kamailio_address>>
>>
>> When you use header "From" transformation (I see Route with vsf),
>> restore may be correct only for exactly the same header "From".
>> Check may be port number is missing/added in  received message header
>> "From".
>>
>> Best regards,
>> Julia
>>
>> On Mon, Nov 13, 2017 at 5:05 PM, Donat Zenichev
>> <donat.zenichev at gmail.com <mailto:donat.zenichev at gmail.com>>>> wrote:
>>
>>     Hi community.
>>     We experience the problem with malformed messages.
>>
>>     First of all, I want to say, that most of time kamailio works well
>>     and nothing happens that can drop sessions.
>>     But from time-to-time something changes (may be in the network)
>>     and kamailio receives requests with malformed headers (To or From
>>     hfs).
>>
>>     The schema:
>>     uplinks ->> kamailio <->> routing server (asterisk)
>>
>>     Malformed messages were received only from asterisk server.
>>     Sip debug on asterisk showed that messages were transmitted
>>     correctly and headers were nice.
>>     But kamailio obtains changed (broken) packets or perhaps can't
>>     read them properly.
>>
>>     How does it look like:
>>     Nov 10 12:37:06 kamailio-name kamailio[965]: INFO: <script>>: Going
>>     to NATMANAGE for BYE from sip:useragent7122 at kamailio_address:5068
>>     (IP=wss:client_address:62881) -
>>     R=sip:dialed_did_service at asterisk_address:50600
>>     ID=1b0044070de406153bf0e4b84d6bb793 at asterisk_address:50600
>>     Nov 10 12:37:06 kamailio-name kamailio[965]: NOTICE: <script>>:
>>     Relaying request to <null>> -
>>     R=sip:dialed_did_service at asterisk_address:50600
>>     ID=1b0044070de406153bf0e4b84d6bb793 at asterisk_address:50600
>>     Nov 10 12:37:06 kamailio-name kamailio[965]: ERROR: <core>>
>>     [parser/parse_addr_spec.c:719]: parse_addr_spec(): unexpected char
>>     [<] in status 6: [<sip:useragent6] .
>>     Nov 10 12:37:06 kamailio-name kamailio[965]: ERROR: <core>>
>>     [parser/parse_from.c:75]: parse_from_header(): bad From header
>>     [<sip:useragent6<+.w>>;tag=jja7l45gd1]
>>     Nov 10 12:37:06 kamailio-name kamailio[965]: ERROR: dialog
>>     [dlg_cseq.c:89]: dlg_cseq_prepare_msg(): cannot parse FROM header
>>     Nov 10 12:37:06 kamailio-name kamailio[937]: ERROR: <core>>
>>     [parser/parse_addr_spec.c:719]: parse_addr_spec(): unexpected char
>>     [<] in status 6: [<sip:useragent6] .
>>     Nov 10 12:37:06 kamailio-name kamailio[937]: ERROR: <core>>
>>     [parser/parse_from.c:75]: parse_from_header(): bad From header
>>     [<sip:useragent6<+.w>>;tag=jja7l45gd1]
>>     Nov 10 12:37:06 kamailio-name kamailio[937]: ERROR: dialog
>>     [dlg_cseq.c:89]: dlg_cseq_prepare_msg(): cannot parse FROM header
>>     Nov 10 12:37:06 kamailio-name kamailio[937]: ERROR: <core>>
>>     [parser/parse_addr_spec.c:719]: parse_addr_spec(): unexpected char
>>     [<] in status 6: [<sip:useragent6] .
>>     Nov 10 12:37:06 kamailio-name kamailio[937]: ERROR: <core>>
>>     [parser/parse_from.c:75]: parse_from_header(): bad From header
>>     [<sip:useragent6<+.w>>;tag=jja7l45gd1]
>>     Nov 10 12:37:06 kamailio-name kamailio[937]: ERROR: uac
>>     [replace.c:783]: restore_uris_reply(): failed to find/parse FROM hdr
>>     Nov 10 12:37:06 kamailio-name kamailio[937]: ERROR: <core>>
>>     [parser/parse_addr_spec.c:719]: parse_addr_spec(): unexpected char
>>     [<] in status 6: [<sip:useragent6] .
>>     Nov 10 12:37:06 kamailio-name kamailio[937]: ERROR: <core>>
>>     [parser/parse_from.c:75]: parse_from_header(): bad From header
>>     [<sip:useragent6<+.w>>;tag=jja7l45gd1]
>>     Nov 10 12:37:06 kamailio-name kamailio[937]: ERROR: pv
>>     [pv_core.c:465]: pv_get_from_attr(): cannot parse From header
>>     Nov 10 12:37:06 kamailio-name kamailio[937]: INFO: <script>>: Skip
>>     manage DEVICE_STATE for BYE from <null>>
>>     (IP=udp:asterisk_address:50600) with (200 - OK) - R=<null>>
>>     ID=1b0044070de406153bf0e4b84d6bb793 at asterisk_address:50600
>>     Nov 10 12:37:06 kamailio-name kamailio[937]: INFO: <script>>:
>>     ------------------------------------MANAGE BYE by
>>     DEVICE_STATE_BYE_MANAGE route - 200 - OK M=BYE
>>     IP=udp:asterisk_address:50600
>>     ID=1b0044070de406153bf0e4b84d6bb793 at asterisk_address:50600
>>     Nov 10 12:37:06 kamailio-name kamailio[937]: ERROR: <core>>
>>     [parser/parse_addr_spec.c:719]: parse_addr_spec(): unexpected char
>>     [<] in status 6: [<sip:useragent6] .
>>     Nov 10 12:37:06 kamailio-name kamailio[937]: ERROR: <core>>
>>     [parser/parse_from.c:75]: parse_from_header(): bad From header
>>     [<sip:useragent6<+.w>>;tag=jja7l45gd1]
>>     Nov 10 12:37:06 kamailio-name kamailio[937]: ERROR: pv
>>     [pv_core.c:465]: pv_get_from_attr(): cannot parse From header
>>     Nov 10 12:37:06 kamailio-name kamailio[937]: ERROR: <core>>
>>     [parser/parse_addr_spec.c:719]: parse_addr_spec(): unexpected char
>>     [<] in status 6: [<sip:useragent6] .
>>     Nov 10 12:37:06 kamailio-name kamailio[937]: ERROR: <core>>
>>     [parser/parse_from.c:75]: parse_from_header(): bad From header
>>     [<sip:useragent6<+.w>>;tag=jja7l45gd1]
>>     Nov 10 12:37:06 kamailio-name kamailio[937]: ERROR: rtpengine
>>     [rtpengine_funcs.c:331]: get_from_tag(): failed to parse From header
>>     Nov 10 12:37:06 kamailio-name kamailio[937]: ERROR: rtpengine
>>     [rtpengine.c:2252]: rtpp_function_call(): can't get From tag
>>     Nov 10 12:37:06 kamailio-name kamailio[937]: ERROR: <core>>
>>     [parser/parse_addr_spec.c:719]: parse_addr_spec(): unexpected char
>>     [<] in status 6: [<sip:useragent6] .
>>     Nov 10 12:37:06 kamailio-name kamailio[937]: ERROR: <core>>
>>     [parser/parse_from.c:75]: parse_from_header(): bad From header
>>     [<sip:useragent6<+.w>>;tag=jja7l45gd1]
>>     Nov 10 12:37:06 kamailio-name kamailio[937]: ERROR: pv
>>     [pv_core.c:465]: pv_get_from_attr(): cannot parse From header
>>     Nov 10 12:37:06 kamailio-name kamailio[937]: ERROR: <core>>
>>     [parser/parse_addr_spec.c:719]: parse_addr_spec(): unexpected char
>>     [<] in status 6: [<sip:useragent6] .
>>     Nov 10 12:37:06 kamailio-name kamailio[937]: ERROR: <core>>
>>     [parser/parse_from.c:75]: parse_from_header(): bad From header
>>     [<sip:useragent6<+.w>>;tag=jja7l45gd1]
>>     Nov 10 12:37:06 kamailio-name kamailio[937]: ERROR: pv
>>     [pv_core.c:465]: pv_get_from_attr(): cannot parse From header
>>
>>     How the packet looks like:
>>     ACK
>>     sip:tt7etmau at bb0pd5t63b26.invalid;alias=client_address~57573~6;transport=ws
>>     SIP/2.0
>>     Via: SIP/2.0/UDP asterisk_address:50600;branch=z9hG4bK117106ca;rport
>>     Route:
>>     <sip:kam2.domain.com:5068;nat=yes;transport=udp;r2=on;ftag=as06869a5d;lr=on;vsf=AAAAAEZZSVVDVV1VRBlUUkUpFQxdVUZYXiRCHU1RQl1HRVNaXhhAQ3RuLnR3aWxpby5jb20-;vst=AAAAAAAAAAAAAAAAAAAAAAAfBwQRQE8NBR9BChIFAwddCgADFEVDQlYudHdpbGlvLmNvbQ--;did=b0c.7331>>,<sip:kam2.callision.com:5068
>>     <http://kam2.callision.com:5068>>;nat=yes;transport=ws;r2=on;ftag=as06869a5d;lr=on;vsf=AAAAAEZZSVVDVV1VRBlUUkUpFQxdVUZYXiRCHU1RQl1HRVNaXhhAQ3RuLnR3aWxpby5jb20-;vst=AAAAAAAAAAAAAAAAAAAAAAAfBwQRQE8NBR9BChIFAwddCgADFEVDQlYudHdpbGlvLmNvbQ--;did=b0c.7331>>
>>     Max-Forwards: 70
>>     From: "19172423539 <tel:%28917%29%20242-3539>>" <sip:19172423539
>>     <tel:%28917%29%20242-3539>>@asterisk_address:50600>>;tag=as06869a5d
>>     To: <sip:useragent7122 at 10.0.1.18:5068
>>     <http://sip:useragent7122@10.0.1.18:5068>>>>;tag=nmv7kmpau3
>>     Contact: <sip:19172423539
>>     <tel:%28917%29%20242-3539>>@asterisk_address:50600>>
>>     Call-ID: 629d5a132c194c536b5f5c1a2a3c6e32 at asterisk_address:50600
>>     CSeq: 102 ACK
>>     User-Agent: asterisk PBX
>>     Content-Length: 0
>>
>>
>>     The transport is used to send messages between asterisk and
>>     kamailio is TCP.
>>     TCP configurations:
>>     tcp_connection_lifetime=3604
>>     tcp_accept_no_cl=yes
>>     tcp_connect_timeout=5
>>     tcp_send_timeout=5
>>     tcp_rd_buf_size=16384
>>     tcp_keepalive=yes
>>     tcp_crlf_ping=yes
>>     tcp_keepcnt=3
>>     tcp_keepidle=30
>>     tcp_keepintvl=15
>>     tcp_max_connections=4096 
>>
>>     I found the idea, that we need to change following parameters:
>>     modparam("uac","restore_mode","auto")
>>     modparam("uac","restore_dlg",1)
>>
>>     to:
>>     modparam("uac","restore_mode","none")
>>     modparam("uac","restore_dlg",0)
>>
>>     I did that, now it looks like all is fine, but I think it can get
>>     back.
>>     Thanks in advance.
>>
>>
>>
>>     -- 
>>     -- 
>>     BR, Donat Zenichev
>>     Wnet VoIP team
>>     Tel Ukraine:  +380(44) 5-900-800
>>     Tel USA: +164(67) 8-174-17
>>     https://w-net.us/ <http://wnet.ua>>
>>
>>     _______________________________________________
>>     Kamailio (SER) - Users Mailing List
>>     sr-users at lists.kamailio.org <mailto:sr-users at lists.kamailio.org>>
>>     https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users
>>     <https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users>>
>>
>>
>>
>>
>> _______________________________________________
>> Kamailio (SER) - Users Mailing List
>> sr-users at lists.kamailio.org
>> https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users

>>-- 
>Daniel-Constantin Mierla
>www.twitter.com/miconda -- www.linkedin.com/in/miconda
>Kamailio Advanced Training, Nov 13-15, 2017, in Berlin - www.asipto.com
>Kamailio World Conference - www.kamailioworld.com


2017-11-13 17:05 GMT+02:00 Donat Zenichev <donat.zenichev@gmail.com>:
Hi community.
We experience the problem with malformed messages.

First of all, I want to say, that most of time kamailio works well and nothing happens that can drop sessions.
But from time-to-time something changes (may be in the network) and kamailio receives requests with malformed headers (To or From hfs).

The schema:
uplinks -> kamailio <-> routing server (asterisk)

Malformed messages were received only from asterisk server.
Sip debug on asterisk showed that messages were transmitted correctly and headers were nice.
But kamailio obtains changed (broken) packets or perhaps can't read them properly.

How does it look like:
Nov 10 12:37:06 kamailio-name kamailio[965]: INFO: <script>: Going to NATMANAGE for BYE from sip:useragent7122@kamailio_address:5068 (IP=wss:client_address:62881) - R=sip:dialed_did_service@asterisk_address:50600 ID=1b0044070de406153bf0e4b84d6bb793@asterisk_address:50600
Nov 10 12:37:06 kamailio-name kamailio[965]: NOTICE: <script>: Relaying request to <null> - R=sip:dialed_did_service@asterisk_address:50600 ID=1b0044070de406153bf0e4b84d6bb793@asterisk_address:50600
Nov 10 12:37:06 kamailio-name kamailio[965]: ERROR: <core> [parser/parse_addr_spec.c:719]: parse_addr_spec(): unexpected char [<] in status 6: [<sip:useragent6] .
Nov 10 12:37:06 kamailio-name kamailio[965]: ERROR: <core> [parser/parse_from.c:75]: parse_from_header(): bad From header [<sip:useragent6<+.w>;tag=jja7l45gd1]
Nov 10 12:37:06 kamailio-name kamailio[965]: ERROR: dialog [dlg_cseq.c:89]: dlg_cseq_prepare_msg(): cannot parse FROM header
Nov 10 12:37:06 kamailio-name kamailio[937]: ERROR: <core> [parser/parse_addr_spec.c:719]: parse_addr_spec(): unexpected char [<] in status 6: [<sip:useragent6] .
Nov 10 12:37:06 kamailio-name kamailio[937]: ERROR: <core> [parser/parse_from.c:75]: parse_from_header(): bad From header [<sip:useragent6<+.w>;tag=jja7l45gd1]
Nov 10 12:37:06 kamailio-name kamailio[937]: ERROR: dialog [dlg_cseq.c:89]: dlg_cseq_prepare_msg(): cannot parse FROM header
Nov 10 12:37:06 kamailio-name kamailio[937]: ERROR: <core> [parser/parse_addr_spec.c:719]: parse_addr_spec(): unexpected char [<] in status 6: [<sip:useragent6] .
Nov 10 12:37:06 kamailio-name kamailio[937]: ERROR: <core> [parser/parse_from.c:75]: parse_from_header(): bad From header [<sip:useragent6<+.w>;tag=jja7l45gd1]
Nov 10 12:37:06 kamailio-name kamailio[937]: ERROR: uac [replace.c:783]: restore_uris_reply(): failed to find/parse FROM hdr
Nov 10 12:37:06 kamailio-name kamailio[937]: ERROR: <core> [parser/parse_addr_spec.c:719]: parse_addr_spec(): unexpected char [<] in status 6: [<sip:useragent6] .
Nov 10 12:37:06 kamailio-name kamailio[937]: ERROR: <core> [parser/parse_from.c:75]: parse_from_header(): bad From header [<sip:useragent6<+.w>;tag=jja7l45gd1]
Nov 10 12:37:06 kamailio-name kamailio[937]: ERROR: pv [pv_core.c:465]: pv_get_from_attr(): cannot parse >From header
Nov 10 12:37:06 kamailio-name kamailio[937]: INFO: <script>: Skip manage DEVICE_STATE for BYE from <null> (IP=udp:asterisk_address:50600) with (200 - OK) - R=<null> ID=1b0044070de406153bf0e4b84d6bb793@asterisk_address:50600
Nov 10 12:37:06 kamailio-name kamailio[937]: INFO: <script>: ------------------------------------MANAGE BYE by DEVICE_STATE_BYE_MANAGE route - 200 - OK M=BYE IP=udp:asterisk_address:50600 ID=1b0044070de406153bf0e4b84d6bb793@asterisk_address:50600
Nov 10 12:37:06 kamailio-name kamailio[937]: ERROR: <core> [parser/parse_addr_spec.c:719]: parse_addr_spec(): unexpected char [<] in status 6: [<sip:useragent6] .
Nov 10 12:37:06 kamailio-name kamailio[937]: ERROR: <core> [parser/parse_from.c:75]: parse_from_header(): bad From header [<sip:useragent6<+.w>;tag=jja7l45gd1]
Nov 10 12:37:06 kamailio-name kamailio[937]: ERROR: pv [pv_core.c:465]: pv_get_from_attr(): cannot parse From header
Nov 10 12:37:06 kamailio-name kamailio[937]: ERROR: <core> [parser/parse_addr_spec.c:719]: parse_addr_spec(): unexpected char [<] in status 6: [<sip:useragent6] .
Nov 10 12:37:06 kamailio-name kamailio[937]: ERROR: <core> [parser/parse_from.c:75]: parse_from_header(): bad From header [<sip:useragent6<+.w>;tag=jja7l45gd1]
Nov 10 12:37:06 kamailio-name kamailio[937]: ERROR: rtpengine [rtpengine_funcs.c:331]: get_from_tag(): failed to parse From header
Nov 10 12:37:06 kamailio-name kamailio[937]: ERROR: rtpengine [rtpengine.c:2252]: rtpp_function_call(): can't get From tag
Nov 10 12:37:06 kamailio-name kamailio[937]: ERROR: <core> [parser/parse_addr_spec.c:719]: parse_addr_spec(): unexpected char [<] in status 6: [<sip:useragent6] .
Nov 10 12:37:06 kamailio-name kamailio[937]: ERROR: <core> [parser/parse_from.c:75]: parse_from_header(): bad From header [<sip:useragent6<+.w>;tag=jja7l45gd1]
Nov 10 12:37:06 kamailio-name kamailio[937]: ERROR: pv [pv_core.c:465]: pv_get_from_attr(): cannot parse From header
Nov 10 12:37:06 kamailio-name kamailio[937]: ERROR: <core> [parser/parse_addr_spec.c:719]: parse_addr_spec(): unexpected char [<] in status 6: [<sip:useragent6] .
Nov 10 12:37:06 kamailio-name kamailio[937]: ERROR: <core> [parser/parse_from.c:75]: parse_from_header(): bad From header [<sip:useragent6<+.w>;tag=jja7l45gd1]
Nov 10 12:37:06 kamailio-name kamailio[937]: ERROR: pv [pv_core.c:465]: pv_get_from_attr(): cannot parse From header

How the packet looks like:
ACK sip:tt7etmau@bb0pd5t63b26.invalid;alias=client_address~57573~6;transport=ws SIP/2.0
Via: SIP/2.0/UDP asterisk_address:50600;branch=z9hG4bK117106ca;rport
Route: <sip:kam2.domain.com:5068;nat=yes;transport=udp;r2=on;ftag=as06869a5d;lr=on;vsf=AAAAAEZZSVVDVV1VRBlUUkUpFQxdVUZYXiRCHU1RQl1HRVNaXhhAQ3RuLnR3aWxpby5jb20-;vst=AAAAAAAAAAAAAAAAAAAAAAAfBwQRQE8NBR9BChIFAwddCgADFEVDQlYudHdpbGlvLmNvbQ--;did=b0c.7331>,<sip:kam2.callision.com:5068;nat=yes;transport=ws;r2=on;ftag=as06869a5d;lr=on;vsf=AAAAAEZZSVVDVV1VRBlUUkUpFQxdVUZYXiRCHU1RQl1HRVNaXhhAQ3RuLnR3aWxpby5jb20-;vst=AAAAAAAAAAAAAAAAAAAAAAAfBwQRQE8NBR9BChIFAwddCgADFEVDQlYudHdpbGlvLmNvbQ--;did=b0c.7331>
Max-Forwards: 70
From: "19172423539" <sip:19172423539@asterisk_address:50600>;tag=as06869a5d
Contact: <sip:19172423539@asterisk_address:50600>
Call-ID: 629d5a132c194c536b5f5c1a2a3c6e32@asterisk_address:50600
CSeq: 102 ACK
User-Agent: asterisk PBX
Content-Length: 0


The transport is used to send messages between asterisk and kamailio is TCP.
TCP configurations:
tcp_connection_lifetime=3604
tcp_accept_no_cl=yes
tcp_connect_timeout=5
tcp_send_timeout=5
tcp_rd_buf_size=16384
tcp_keepalive=yes
tcp_crlf_ping=yes
tcp_keepcnt=3
tcp_keepidle=30
tcp_keepintvl=15
tcp_max_connections=4096 

I found the idea, that we need to change following parameters:
modparam("uac","restore_mode","auto")
modparam("uac","restore_dlg",1)

to:
modparam("uac","restore_mode","none")
modparam("uac","restore_dlg",0)

I did that, now it looks like all is fine, but I think it can get back.
Thanks in advance.



--
-- 
BR, Donat Zenichev
Wnet VoIP team
Tel Ukraine:  +380(44) 5-900-800
Tel USA: +164(67) 8-174-17
https://w-net.us/



--
-- 
BR, Donat Zenichev
Wnet VoIP team
Tel Ukraine:  +380(44) 5-900-800
Tel USA: +164(67) 8-174-17
https://w-net.us/



--
-- 
BR, Donat Zenichev
Wnet VoIP team
Tel Ukraine:  +380(44) 5-900-800
Tel USA: +164(67) 8-174-17
https://w-net.us/