How to test TURN HA ?

[rgarrigue]

Hi there

I'm interested in using voip_patrol to test a high availability TURN setup (using coturn). How can I test that ? Tried a naive /git/voip_patrol/voip_patrol -c ./test.xml -o result.json with this test.xml

<config>
  <actions>
    <action type="turn" enabled="true" server="turn.test:3478" username="test" password="test"/>
    <action type="wait" complete/>
  </actions>
</config>

Note, I intend turn.test to answer at least 2 IPs, this is what I meant by high availability

The output said

[08:02:37.974][INFO] pjsip_config->tsx.t1 :500

Prepared for Action!
[08:02:37.974][INFO] JSON result file:results.json

[08:02:37.974][INFO] JSON result file:result.json

[08:02:37.974][INFO] 
* * * * * * *
voip_patrol version: 0.2.3
configuration: ./test.xml
log file (voip_patrol): result.json
log file (pjsua): result.json.pjsua
output file: result.json
public_address: 
bound_address: 
* * * * * * *

08:02:37.985         os_core_unix.c !pjlib 2.10-dev for POSIX initialized
08:02:37.986         sip_endpoint.c  .Creating endpoint instance...
08:02:37.987                  pjlib  .select() I/O Queue created (0x559b3ede1d08)
08:02:37.987         sip_endpoint.c  .Module "mod-msg-print" registered
08:02:37.987        sip_transport.c  .Transport manager created.
08:02:37.987           pjsua_core.c  .PJSUA state changed: NULL --> CREATED
[08:02:38.004][INFO] main: TLS tcfg.tlsConfig.ca_list      :tls/ca_list.pem
[08:02:38.004][INFO] main: TLS tcfg.tlsConfig.certFile     :tls/certificate.pem
[08:02:38.004][INFO] main: TLS tcfg.tlsConfig.privKeyFile  :tls/key.pem
[08:02:38.004][INFO] main: TLS tcfg.tlsConfig.verifyServer :0
[08:02:38.004][INFO] main: TLS tcfg.tlsConfig.verifyClient :0
[08:02:38.004][INFO] main: TLS supported :tls/certificate.pem
[08:02:38.004][INFO] createAccount: [0][sip:default]
[08:02:38.004][INFO] createDefaultAccount created:voice_ref_files/reference_8000.wav
[08:02:38.004][INFO] process ===> actions
[08:02:38.004][INFO] process ===> action/turn
[08:02:38.004][ERROR] process: params not found for action:turn

[08:02:38.005][INFO] process ===> action/wait
[08:02:38.005][INFO] set_param param name:complete val:
[08:02:38.005][INFO] do_wait duration_ms:0 complete all tests:1
[08:02:38.005][INFO] do_wait: completed
[08:02:38.005][INFO] main: wait complete all...
[08:02:38.005][INFO] do_wait duration_ms:0 complete all tests:0
[08:02:38.005][INFO] do_wait: completed
[08:02:38.005][INFO] main: checking alerts...
[08:02:38.006][INFO] send smtp
[08:02:38.006][INFO] main: hangup all calls...
[08:02:39.504][INFO] main: Success
[08:02:39.504][INFO] main: Watch completed, exiting  /('l')

result.json is empty, result.json.pjsua says

08:02:37.987         sip_endpoint.c  .Module "mod-pjsua-log" registered
08:02:37.987         sip_endpoint.c  .Module "mod-tsx-layer" registered
08:02:37.987         sip_endpoint.c  .Module "mod-stateful-util" registered
08:02:37.987         sip_endpoint.c  .Module "mod-ua" registered
08:02:37.987         sip_endpoint.c  .Module "mod-100rel" registered
08:02:37.987         sip_endpoint.c  .Module "mod-pjsua" registered
08:02:37.988         sip_endpoint.c  .Module "mod-invite" registered
08:02:37.992             alsa_dev.c  ..ALSA driver found 0 devices
08:02:37.992             alsa_dev.c  ..ALSA initialized
08:02:38.000                  pjlib  ..select() I/O Queue created (0x559b3edff0c8)
08:02:38.000           conference.c  ..Creating conference bridge with 514 ports
08:02:38.000           Master/sound  ..Using delay buffer with WSOLA.
08:02:38.004         sip_endpoint.c  .Module "mod-evsub" registered
08:02:38.004         sip_endpoint.c  .Module "mod-presence" registered
08:02:38.004                evsub.c  .Event pkg "presence" registered by mod-presence
08:02:38.004         sip_endpoint.c  .Module "mod-mwi" registered
08:02:38.004                evsub.c  .Event pkg "message-summary" registered by mod-mwi
08:02:38.004         sip_endpoint.c  .Module "mod-refer" registered
08:02:38.004                evsub.c  .Event pkg "refer" registered by mod-refer
08:02:38.004         sip_endpoint.c  .Module "mod-pjsua-pres" registered
08:02:38.004         sip_endpoint.c  .Module "mod-pjsua-im" registered
08:02:38.004         sip_endpoint.c  .Module "mod-pjsua-options" registered
08:02:38.004           pjsua_core.c  .1 SIP worker threads created
08:02:38.004           pjsua_core.c  .pjsua version 2.10-dev for Linux-5.4.0.62/x86_64/glibc-2.28 initialized
08:02:38.004           pjsua_core.c  .PJSUA state changed: CREATED --> INIT
08:02:38.004           pjsua_core.c  SIP UDP socket reachable at 10.0.2.100:5070
08:02:38.004      udp0x559b3eea58a0  SIP UDP transport started, published address is 10.0.2.100:5070
08:02:38.004             tcptp:5070  SIP TCP listener ready for incoming connections at 10.0.2.100:5070
08:02:38.004             tlstp:5071  SIP TLS listener is ready for incoming connections at 10.0.2.100:5071
08:02:38.004            pjsua_aud.c  Setting null sound device..
08:02:38.004            pjsua_aud.c  .Opening null sound device..
08:02:38.004           pjsua_core.c  PJSUA state changed: INIT --> STARTING
08:02:38.004         sip_endpoint.c  .Module "mod-unsolicited-mwi" registered
08:02:38.004           pjsua_core.c  .PJSUA state changed: STARTING --> RUNNING
08:02:38.004            pjsua_acc.c  Adding account: id=sip:default
08:02:38.004            pjsua_acc.c  .Account sip:default added with id 0
08:02:38.056           pjsua_core.c  Shutting down, flags=0...
08:02:38.056           pjsua_core.c  PJSUA state changed: RUNNING --> CLOSING
08:02:38.065           pjsua_call.c  .Hangup all calls..
08:02:38.065          pjsua_media.c  .Call 0: deinitializing media..
08:02:38.065          pjsua_media.c  .Call 1: deinitializing media..
08:02:38.065          pjsua_media.c  .Call 2: deinitializing media..
08:02:38.065          pjsua_media.c  .Call 3: deinitializing media..
... (shortened) ...
08:02:38.065          pjsua_media.c  .Call 511: deinitializing media..
08:02:38.066           pjsua_pres.c  .Shutting down presence..
08:02:39.004            pjsua_aud.c  .Closing sound device after idle for 1 second(s)
08:02:39.004            pjsua_aud.c  ..Closing null sound device..
08:02:39.075           pjsua_core.c  .Destroying...
08:02:39.075          pjsua_media.c  .Shutting down media..
08:02:39.501         sip_endpoint.c  .Destroying endpoint instance..
08:02:39.501      sip_transaction.c  .Stopping transaction layer module
08:02:39.501      sip_transaction.c  .Stopped transaction layer module
08:02:39.501         sip_endpoint.c  .Module "mod-unsolicited-mwi" unregistered
08:02:39.501         sip_endpoint.c  .Module "mod-pjsua-options" unregistered
08:02:39.501         sip_endpoint.c  .Module "mod-pjsua-im" unregistered
08:02:39.501         sip_endpoint.c  .Module "mod-pjsua-pres" unregistered
08:02:39.501         sip_endpoint.c  .Module "mod-pjsua" unregistered
08:02:39.501         sip_endpoint.c  .Module "mod-stateful-util" unregistered
08:02:39.501         sip_endpoint.c  .Module "mod-refer" unregistered
08:02:39.501         sip_endpoint.c  .Module "mod-mwi" unregistered
08:02:39.501         sip_endpoint.c  .Module "mod-presence" unregistered
08:02:39.501         sip_endpoint.c  .Module "mod-evsub" unregistered
08:02:39.501         sip_endpoint.c  .Module "mod-invite" unregistered
08:02:39.501         sip_endpoint.c  .Module "mod-100rel" unregistered
08:02:39.501         sip_endpoint.c  .Module "mod-ua" unregistered
08:02:39.501      sip_transaction.c  .Transaction layer module destroyed
08:02:39.501         sip_endpoint.c  .Module "mod-tsx-layer" unregistered
08:02:39.501         sip_endpoint.c  .Module "mod-msg-print" unregistered
08:02:39.501         sip_endpoint.c  .Module "mod-pjsua-log" unregistered
08:02:39.501        sip_transport.c  .Destroying transport manager
08:02:39.503      udp0x559b3eea58a0  .SIP UDP transport destroyed
08:02:39.503             tcptp:5070  .SIP TCP transport destroyed
08:02:39.503             tlstp:5071  .SIP TLS transport destroyed
08:02:39.503                timer.c  .Dumping timer heap:
08:02:39.503                timer.c  .  Cur size: 0 entries, max: 3070
08:02:39.503         sip_endpoint.c  .Endpoint 0x559b3edd6178 destroyed
08:02:39.503           pjsua_core.c  .PJSUA state changed: CLOSING --> NULL
08:02:39.503           pjsua_core.c  .PJSUA destroyed...

As I said, I tried the naive way, I guess I need some more configuration. Could you provide me some guidance about how to setup a meaningful test ? The best would be a call over the TURN, dunno if there is an easy setup to achieve that, like a mock server ?

[jchavanton]

Can you look at the second log file (more verbose) result.json.pjsua

-o,--output <result.json>         json result file name, another file suffixed with ".pjsua" will also be created with all the logs from PJ-SIP

The ICE negotiation and TURN is quite verbose. I need to expose authentication password type, in case this is your problem.

acc_cfg.natConfig.turnPasswordType = PJ_STUN_PASSWD_PLAIN; // PJ_STUN_PASSWD_HASHED;

[rgarrigue]

The second log file ".json.pjsua" file is pasted above, the first one ".json" being empty

I'm 100% sure about the password, I made some test using our softphone app, it worked properly

[jchavanton]

You need to use the latest master, TURN action was added recently This is not the right log file

Once you run ./voip_patrol -p 1234 -c xml/your_test.xml

You will have a file called results.json.pjsua witch will contain all the logs about ICE/TURN

14:05:55.275          pjsua_media.c  .Call 0: initializing media..
14:05:55.275                icetp00  ..Creating ICE stream transport with 2 component(s)                                                                                                                    
14:05:55.275                icetp00  ...Comp 1/0: host candidate 192.168.0.111:6965 (tpid=64) added
14:05:55.275                icetp00  ...Comp 1/1: host candidate 192.168.0.132:6965 (tpid=64) added
14:05:55.275   udprel0x55a26c14ccc0  ...TURN client session created
14:05:55.275   udprel0x55a26c14ccc0  ...Resolving 32.117.21.130 with DNS A
14:05:55.275   udprel0x55a26c14ccc0  ...State changed Null --> Resolving
14:05:55.275                icetp00  ...TURN client state changed Null --> Resolving
14:05:55.275   udprel0x55a26c14ccc0  ...State changed Resolving --> Resolved
14:05:55.275                icetp00  ...TURN client state changed Resolving --> Resolved
14:05:55.275   udprel0x55a26c14ccc0  ...Connecting to 32.117.21.130:3678
14:05:55.275   udprel0x55a26c14ccc0  ...State changed Resolved --> Allocating
14:05:55.275                icetp00  ...TURN client state changed Resolved --> Allocating
14:05:55.276   udprel0x55a26c14ccc0  ....TX 52 bytes STUN message to 32.117.21.130:3678:
--- begin STUN message ---
STUN Allocate request
 Hdr: length=32, magic=2112a442, tsx_id=000018d74fe5af045b39d0d4
 Attributes:
  REQUESTED-TRANSPORT: length=4, value=285212672 (0x11000000)
  SOFTWARE: length=17, value="pjnath-2.10.0-dev"
--- end of STUN message ---

[rgarrigue]

So, I cloned the repo, built the container (build_image.sh), then run it with the above mentioned turn configuration, no mention of STUN / TURN / ICE in the logs again.

Can you c/c your conf.xml file producing your log ?

[jchavanton]

build_image.sh will run docker build using the Dockerfile, it was building the previous tag 0.2.5 I just made a patch release to 0.2.7 I also added the parameter password_hashed defaulting to plain. I will also update the image in the public docker repo. You can test again after pulling from master.