search

pjsip / pjproject

PJSIP project
http://www.pjsip.org
GNU General Public License v2.0
2k stars 767 forks source link

423 (Interval Too Brief) response in SIP registration is not handled #4038

Closed jo7ueb closed 2 weeks ago

jo7ueb commented 4 weeks ago

Describe the bug

I'm trying with provided "Hello World" and found some issues.

My SIP server accepts registration packet with Expires header value larger than or equal to 3600. PSIP sends Expires header with value 300, causes 423 (Interval Too Brief) response from server.

1031 implements automatic handling of the response, but it not worked for me.

Steps to reproduce

  1. Run Official Python Hello World with modification in SIP host/authentication settings
  2. Monitor SIP packet w/ Wireshark

PJSIP version

2.14.1

Context

This issue is oberved in WSL2.

Log, call stack, etc

03:04:39.490         os_core_unix.c !pjlib 2.14.1 for POSIX initialized
03:04:39.490         sip_endpoint.c  .Creating endpoint instance...
03:04:39.490                  pjlib  .select() I/O Queue created (0x55f50c60abd8)
03:04:39.490         sip_endpoint.c  .Module "mod-msg-print" registered
03:04:39.490        sip_transport.c  .Transport manager created.
03:04:39.490           pjsua_core.c  .PJSUA state changed: NULL --> CREATED
03:04:39.490         sip_endpoint.c  .Module "mod-pjsua-log" registered
03:04:39.490         sip_endpoint.c  .Module "mod-tsx-layer" registered
03:04:39.491         sip_endpoint.c  .Module "mod-stateful-util" registered
03:04:39.491         sip_endpoint.c  .Module "mod-ua" registered
03:04:39.491         sip_endpoint.c  .Module "mod-100rel" registered
03:04:39.491         sip_endpoint.c  .Module "mod-pjsua" registered
03:04:39.491         sip_endpoint.c  .Module "mod-invite" registered
03:04:39.492             alsa_dev.c  ..ALSA driver found 0 devices
03:04:39.492             alsa_dev.c  ..ALSA initialized
03:04:39.492                  pjlib  ..select() I/O Queue created (0x55f50c661468)
03:04:39.493         sip_endpoint.c  .Module "mod-evsub" registered
03:04:39.493         sip_endpoint.c  .Module "mod-presence" registered
03:04:39.493         sip_endpoint.c  .Module "mod-mwi" registered
03:04:39.493         sip_endpoint.c  .Module "mod-refer" registered
03:04:39.493         sip_endpoint.c  .Module "mod-pjsua-pres" registered
03:04:39.493         sip_endpoint.c  .Module "mod-pjsua-im" registered
03:04:39.493         sip_endpoint.c  .Module "mod-pjsua-options" registered
03:04:39.493           pjsua_core.c  .1 SIP worker threads created
03:04:39.493           pjsua_core.c  .pjsua version 2.14.1 for Linux-5.15.133.1/x86_64/glibc-2.35 initialized
03:04:39.493           pjsua_core.c  .PJSUA state changed: CREATED --> INIT
03:04:39.493           pjsua_core.c  SIP UDP socket reachable at 172.22.224.223:5060
03:04:39.493      udp0x55f50c670290  SIP UDP transport started, published address is 172.22.224.223:5060
03:04:39.493           pjsua_core.c  PJSUA state changed: INIT --> STARTING
03:04:39.493         sip_endpoint.c  .Module "mod-unsolicited-mwi" registered
03:04:39.493           pjsua_core.c  .PJSUA state changed: STARTING --> RUNNING
03:04:39.494            pjsua_acc.c  Adding account: id=sip:USERNAME@SIPSERVER
03:04:39.494            pjsua_acc.c  .Account sip:USERNAME@SIPSERVER added with id 0
03:04:39.494            pjsua_acc.c  .Acc 0: setting registration..
03:04:39.494           pjsua_core.c  ...TX 479 bytes Request msg REGISTER/cseq=3160 (tdta0x55f50c688258) to UDP 192.168.0.253:5060:
REGISTER sip:192.168.0.253 SIP/2.0
Via: SIP/2.0/UDP 172.22.224.223:5060;rport;branch=z9hG4bKPj39f1fMklJD8Ngor6yTM8UB4SFOpzwKzr
Max-Forwards: 70
From: <sip:USERNAME@SIPSERVER>;tag=Jotqcg774ZlqXicNS0BcbBbkBQxsNBK9
To: <sip:USERNAME@SIPSERVER>
Call-ID: TlzUgS-I9TV.9pQhDac8vdH7IKxk.aZb
CSeq: 3160 REGISTER
Contact: <sip:4@172.22.224.223:5060;ob>
Expires: 300
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Content-Length:  0

--end msg--
03:04:39.494            pjsua_acc.c  ..Acc 0: Registration sent
03:04:39.993           pjsua_core.c  .TX 479 bytes Request msg REGISTER/cseq=3160 (tdta0x55f50c688258) to UDP 192.168.0.253:5060:
REGISTER sip:192.168.0.253 SIP/2.0
Via: SIP/2.0/UDP 172.22.224.223:5060;rport;branch=z9hG4bKPj39f1fMklJD8Ngor6yTM8UB4SFOpzwKzr
Max-Forwards: 70
From: <sip:USERNAME@SIPSERVER>;tag=Jotqcg774ZlqXicNS0BcbBbkBQxsNBK9
To: <sip:USERNAME@SIPSERVER>
Call-ID: TlzUgS-I9TV.9pQhDac8vdH7IKxk.aZb
CSeq: 3160 REGISTER
Contact: <sip:4@172.22.224.223:5060;ob>
Expires: 300
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Content-Length:  0

--end msg--
03:04:40.994           pjsua_core.c  .TX 479 bytes Request msg REGISTER/cseq=3160 (tdta0x55f50c688258) to UDP 192.168.0.253:5060:
REGISTER sip:192.168.0.253 SIP/2.0
Via: SIP/2.0/UDP 172.22.224.223:5060;rport;branch=z9hG4bKPj39f1fMklJD8Ngor6yTM8UB4SFOpzwKzr
Max-Forwards: 70
From: <sip:USERNAME@SIPSERVER>;tag=Jotqcg774ZlqXicNS0BcbBbkBQxsNBK9
To: <sip:USERNAME@SIPSERVER>
Call-ID: TlzUgS-I9TV.9pQhDac8vdH7IKxk.aZb
CSeq: 3160 REGISTER
Contact: <sip:4@172.22.224.223:5060;ob>
Expires: 300
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Content-Length:  0

--end msg--
03:04:42.993           pjsua_core.c  .TX 479 bytes Request msg REGISTER/cseq=3160 (tdta0x55f50c688258) to UDP 192.168.0.253:5060:
REGISTER sip:192.168.0.253 SIP/2.0
Via: SIP/2.0/UDP 172.22.224.223:5060;rport;branch=z9hG4bKPj39f1fMklJD8Ngor6yTM8UB4SFOpzwKzr
Max-Forwards: 70
From: <sip:USERNAME@SIPSERVER>;tag=Jotqcg774ZlqXicNS0BcbBbkBQxsNBK9
To: <sip:USERNAME@SIPSERVER>
Call-ID: TlzUgS-I9TV.9pQhDac8vdH7IKxk.aZb
CSeq: 3160 REGISTER
Contact: <sip:4@172.22.224.223:5060;ob>
Expires: 300
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Content-Length:  0

--end msg--
03:04:46.992           pjsua_core.c  .TX 479 bytes Request msg REGISTER/cseq=3160 (tdta0x55f50c688258) to UDP 192.168.0.253:5060:
REGISTER sip:192.168.0.253 SIP/2.0
Via: SIP/2.0/UDP 172.22.224.223:5060;rport;branch=z9hG4bKPj39f1fMklJD8Ngor6yTM8UB4SFOpzwKzr
Max-Forwards: 70
From: <sip:USERNAME@SIPSERVER>;tag=Jotqcg774ZlqXicNS0BcbBbkBQxsNBK9
To: <sip:USERNAME@SIPSERVER>
Call-ID: TlzUgS-I9TV.9pQhDac8vdH7IKxk.aZb
CSeq: 3160 REGISTER
Contact: <sip:4@172.22.224.223:5060;ob>
Expires: 300
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Content-Length:  0

--end msg--
03:04:49.502           pjsua_core.c !Shutting down, flags=0...
03:04:49.502           pjsua_core.c  PJSUA state changed: RUNNING --> CLOSING
03:04:49.509           pjsua_call.c  .Hangup all calls..
03:04:49.509          pjsua_media.c  .Call 0: deinitializing media..
03:04:49.509          pjsua_media.c  .Call 1: deinitializing media..
03:04:49.509          pjsua_media.c  .Call 2: deinitializing media..
03:04:49.509          pjsua_media.c  .Call 3: deinitializing media..
03:04:49.509           pjsua_pres.c  .Shutting down presence..
03:04:49.509            pjsua_acc.c  .Acc 0: setting unregistration..
03:04:49.510              sip_reg.c  ..Unable to send request, regc has another transaction pending
03:04:49.510            pjsua_acc.c  ..Unable to create/send REGISTER: Object is busy (PJSIP_EBUSY) [status=171001]
03:04:50.992           pjsua_core.c  ..TX 479 bytes Request msg REGISTER/cseq=3160 (tdta0x55f50c688258) to UDP 192.168.0.253:5060:
REGISTER sip:192.168.0.253 SIP/2.0
Via: SIP/2.0/UDP 172.22.224.223:5060;rport;branch=z9hG4bKPj39f1fMklJD8Ngor6yTM8UB4SFOpzwKzr
Max-Forwards: 70
From: <sip:USERNAME@SIPSERVER>;tag=Jotqcg774ZlqXicNS0BcbBbkBQxsNBK9
To: <sip:USERNAME@SIPSERVER>
Call-ID: TlzUgS-I9TV.9pQhDac8vdH7IKxk.aZb
CSeq: 3160 REGISTER
Contact: <sip:4@172.22.224.223:5060;ob>
Expires: 300
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Content-Length:  0

--end msg--
03:04:53.561           pjsua_core.c  .Destroying...
03:04:53.561        sip_transport.c  .Transport udp0x55f50c670290 shutting down, force=0
03:04:53.561          pjsua_media.c  .Shutting down media..
03:04:53.571      sip_transaction.c  .Stopping transaction layer module
03:04:53.571            pjsua_acc.c  ....SIP registration failed, status=503 (Service Unavailable)
03:04:53.571            pjsua_acc.c  ....Scheduling re-registration retry for acc 0 in 1 seconds..
***OnRegState: Service Unavailable
03:04:53.571      sip_transaction.c  .Stopped transaction layer module
03:04:53.571         sip_endpoint.c  .Module "mod-unsolicited-mwi" unregistered
03:04:53.571         sip_endpoint.c  .Module "mod-pjsua-options" unregistered
03:04:53.571         sip_endpoint.c  .Module "mod-pjsua-im" unregistered
03:04:53.571         sip_endpoint.c  .Module "mod-pjsua-pres" unregistered
03:04:53.571         sip_endpoint.c  .Module "mod-pjsua" unregistered
03:04:53.571         sip_endpoint.c  .Module "mod-stateful-util" unregistered
03:04:53.571         sip_endpoint.c  .Module "mod-refer" unregistered
03:04:53.571         sip_endpoint.c  .Module "mod-mwi" unregistered
03:04:53.571         sip_endpoint.c  .Module "mod-presence" unregistered
03:04:53.571         sip_endpoint.c  .Module "mod-evsub" unregistered
03:04:53.571         sip_endpoint.c  .Module "mod-invite" unregistered
03:04:53.571         sip_endpoint.c  .Module "mod-100rel" unregistered
03:04:53.571         sip_endpoint.c  .Module "mod-ua" unregistered
03:04:53.571      sip_transaction.c  .Transaction layer module destroyed
03:04:53.571         sip_endpoint.c  .Module "mod-tsx-layer" unregistered
03:04:53.571         sip_endpoint.c  .Module "mod-msg-print" unregistered
03:04:53.571         sip_endpoint.c  .Module "mod-pjsua-log" unregistered
03:04:53.573      udp0x55f50c670290  .SIP UDP transport destroyed
03:04:53.573                timer.c  .Dumping timer heap:
03:04:53.573                timer.c  .  Cur size: 1 entries, max: 3070
03:04:53.573                timer.c  .  Entries:
03:04:53.573                timer.c  .    _id   Id      Elapsed Source
03:04:53.573                timer.c  .    ----------------------------------
03:04:53.573                timer.c  .    1     1       1.110   ../src/pjsua-lib/pjsua_acc.c:4145
03:04:53.573         sip_endpoint.c  .Endpoint 0x55f50c600c58 destroyed
03:04:53.573           pjsua_core.c  .PJSUA state changed: CLOSING --> NULL
03:04:53.573           pjsua_core.c  .PJSUA destroyed...
sauwming commented 3 weeks ago

This should be covered by the test case tests/pjsua/scripts-recvfrom/209a_reg_handle_423_ok.py

Unfortunately the log doesn't show the 423 response by the server, so we can't tell what went wrong.

jo7ueb commented 2 weeks ago

@sauwming Thank you for the comment. I found that my trouble is WSL's NAT specific issue.

Here's how it was going:

  1. My application (running in WSL2) send register packet to SIP server
  2. WSL NAT functionality rewrites packet source addr to host Window's IP addr
  3. My packet reaches to SIP server, then SIP server return packet to Windows host

  4. WSL NAT somehow lost the packet

    Anyway, NAT is something we want to avoid in simplicity, then I found mirror-mode worked for me. https://learn.microsoft.com/en-us/windows/wsl/networking#mirrored-mode-networking

So there's no issue in pjsip, thanks for your coorperations.