search

pion / turn

Pion TURN, an API for building TURN clients and servers
MIT License
1.87k stars 319 forks source link

udp example of turnc-lient can not relay by coturn server. #413

Closed zwikst closed 2 months ago

zwikst commented 2 months ago

Your environment.

What did you do?

Build udp executable in examples/turn-client/udp. Then use it to test coturn server.

What did you expect?

It will success. Because the target turn server is an online workable one.

What happened?

Rarely succeeds. Mostly panic when failed.

Here is the udp client log:

$ PION_LOG_TRACE=all ./udp -host 116.*.*.* -port 49100 -ping -user 1726132777:testuser=*****
turnc DEBUG: 09:14:37.543188 client.go:110: Resolved STUN server 116.*.*.*:49100 to 116.*.*.*:49100
turnc DEBUG: 09:14:37.543862 client.go:119: Resolved TURN server 116.*.*.*:49100 to 116.*.*.*:49100
turnc TRACE: 09:14:37.544209 client.go:428: Start Allocate request transaction sCm1O9EaUj6u+zse to 116.*.*.*:49100
turnc TRACE: 09:14:37.568892 client.go:428: Start Allocate request transaction M/wReF4IeYCqdDV8 to 116.*.*.*:49100
turnc DEBUG: 09:14:37.592873 udp_conn.go:66: Initial lifetime: 600 seconds
turnc DEBUG: 09:14:37.593104 udp_conn.go:81: Started refresh allocation timer
turnc DEBUG: 09:14:37.593547 udp_conn.go:84: Started refresh permission timer
2024/09/12 09:14:37 relayed-address=116.*.*.*:49120
turnc TRACE: 09:14:37.594805 client.go:428: Start Binding request transaction kJ6+6WeOQ41yoQIM to 116.*.*.*:49100
turnc TRACE: 09:14:37.618165 client.go:428: Start CreatePermission request transaction Q2Uhx/fZ7Q+4LkPB to 116.*.*.*:49100
turnc DEBUG: 09:14:37.641625 allocation.go:173: Set new nonce with 16 bytes
turnc DEBUG: 09:14:37.642045 allocation.go:56: Refresh allocation: 438, got new nonce.
turnc TRACE: 09:14:37.643192 client.go:428: Start CreatePermission request transaction jH1698q8BrxmZF2M to 116.*.*.*:49100
2024/09/12 09:14:37 Failed to ping: CreatePermission error response (error 400: Bad Request)
turnc DEBUG: 09:14:37.667157 allocation.go:77: Send refresh request (dontWait=true)
turnc TRACE: 09:14:37.667548 client.go:428: Start Refresh request transaction 3Hi5VsPOGmN8bRSg to 116.*.*.*:49100
turnc DEBUG: 09:14:37.667994 allocation.go:84: Refresh request sent
turnc DEBUG: 09:14:37.668573 client.go:177: Failed to read: read udp4 0.0.0.0:58976: use of closed network connection. Exiting loop
panic: Failed to ping: CreatePermission error response (error 400: Bad Request)

goroutine 1 [running]:
log.Panicf({0x8196385, 0x12}, {0x891befc, 0x1, 0x1})
        /home/*****/local/go/src/log/log.go:439 +0x9d
main.main()
        /home/*****/github/pion/turn/examples/turn-client/udp/main.go:94 +0x847

$ PION_LOG_TRACE=all ./udp -host 116.*.*.* -port 49100 -ping -user 1726132831:testuser=*****
turnc DEBUG: 09:15:31.941961 client.go:110: Resolved STUN server 116.*.*.*:49100 to 116.*.*.*:49100
turnc DEBUG: 09:15:31.942638 client.go:119: Resolved TURN server 116.*.*.*:49100 to 116.*.*.*:49100
turnc TRACE: 09:15:31.943484 client.go:428: Start Allocate request transaction pBREIwU/ssPr1m5b to 116.*.*.*:49100
turnc TRACE: 09:15:31.965265 client.go:428: Start Allocate request transaction gnY02G4sdQ2xQkoY to 116.*.*.*:49100
turnc DEBUG: 09:15:31.985697 udp_conn.go:66: Initial lifetime: 600 seconds
turnc DEBUG: 09:15:31.986110 udp_conn.go:81: Started refresh allocation timer
turnc DEBUG: 09:15:31.986217 udp_conn.go:84: Started refresh permission timer
2024/09/12 09:15:31 relayed-address=116.*.*.*:49196
turnc TRACE: 09:15:31.986882 client.go:428: Start Binding request transaction 40srG6lS3P+0pWx8 to 116.*.*.*:49100
turnc TRACE: 09:15:32.007152 client.go:428: Start CreatePermission request transaction 9yLypda2x1bBzDDW to 116.*.*.*:49100
turnc DEBUG: 09:15:32.029683 allocation.go:173: Set new nonce with 16 bytes
turnc DEBUG: 09:15:32.029889 allocation.go:56: Refresh allocation: 438, got new nonce.
turnc TRACE: 09:15:32.031456 client.go:428: Start CreatePermission request transaction gerswKixn8njVN+f to 116.*.*.*:49100
2024/09/12 09:15:32 Failed to ping: CreatePermission error response (error 400: Bad Request)
turnc DEBUG: 09:15:32.053403 allocation.go:77: Send refresh request (dontWait=true)
turnc TRACE: 09:15:32.053849 client.go:428: Start Refresh request transaction pQ0Nsdq3Bdqct6Eh to 116.*.*.*:49100
turnc DEBUG: 09:15:32.054302 allocation.go:84: Refresh request sent
turnc DEBUG: 09:15:32.055093 client.go:177: Failed to read: read udp4 0.0.0.0:40123: use of closed network connection. Exiting loop
panic: Failed to ping: CreatePermission error response (error 400: Bad Request)

goroutine 1 [running]:
log.Panicf({0x8196385, 0x12}, {0x9cd7efc, 0x1, 0x1})
        /home/*****/local/go/src/log/log.go:439 +0x9d
main.main()
        /home/*****/github/pion/turn/examples/turn-client/udp/main.go:94 +0x847

The below is coturn log:

2024-09-12T09:14:06+0800(1): INFO: log file opened: /log/turnserver_2024-09-12.log
2024-09-12T09:14:06+0800(1): ERROR: You cannot define external IP more than once in the configuration
2024-09-12T09:14:06+0800(1): INFO: Coturn Version Coturn-4.6.2 'Gorst'
2024-09-12T09:14:06+0800(1): INFO: Max number of open files/sockets allowed for this process: 1048576
2024-09-12T09:14:06+0800(1): INFO: Due to the open files/sockets limitation, max supported number of TURN Sessions possible is: 524000 (approximately)
2024-09-12T09:14:06+0800(1): INFO: 

==== Show him the instruments, Practical Frost: ====

2024-09-12T09:14:06+0800(1): INFO: OpenSSL compile-time version: OpenSSL 3.0.11 19 Sep 2023 (0x300000b0)
2024-09-12T09:14:06+0800(1): INFO: TLS 1.3 supported
2024-09-12T09:14:06+0800(1): INFO: DTLS 1.2 supported
2024-09-12T09:14:06+0800(1): INFO: TURN/STUN ALPN supported
2024-09-12T09:14:06+0800(1): INFO: Third-party authorization (oAuth) supported
2024-09-12T09:14:06+0800(1): INFO: GCM (AEAD) supported
2024-09-12T09:14:06+0800(1): INFO: SQLite supported, default database location is /var/lib/coturn/turndb
2024-09-12T09:14:06+0800(1): INFO: Redis supported
2024-09-12T09:14:06+0800(1): INFO: PostgreSQL supported
2024-09-12T09:14:06+0800(1): INFO: MySQL supported
2024-09-12T09:14:06+0800(1): INFO: MongoDB supported
2024-09-12T09:14:06+0800(1): INFO: Default Net Engine version: 3 (UDP thread per CPU core)
2024-09-12T09:14:06+0800(1): INFO: Domain name: 
2024-09-12T09:14:06+0800(1): INFO: Default realm: testrealm
2024-09-12T09:14:06+0800(1): WARNING: cannot find certificate file: turn_server_cert.pem (1)
2024-09-12T09:14:06+0800(1): WARNING: cannot start TLS and DTLS listeners because certificate file is not set properly
2024-09-12T09:14:06+0800(1): WARNING: cannot find private key file: turn_server_pkey.pem (1)
2024-09-12T09:14:06+0800(1): WARNING: cannot start TLS and DTLS listeners because private key file is not set properly
2024-09-12T09:14:06+0800(1): INFO: Certificate file found: //turn_server_cert.pem
2024-09-12T09:14:06+0800(1): INFO: Private key file found: //turn_server_pkey.pem
2024-09-12T09:14:06+0800(1): WARNING: NO EXPLICIT LISTENER ADDRESS(ES) ARE CONFIGURED
2024-09-12T09:14:06+0800(1): INFO: ===========Discovering listener addresses: =========
2024-09-12T09:14:06+0800(1): INFO: Listener address to use: 127.0.0.1
2024-09-12T09:14:06+0800(1): INFO: Listener address to use: 172.19.0.4
2024-09-12T09:14:06+0800(1): INFO: Listener address to use: 172.20.0.3
2024-09-12T09:14:06+0800(1): INFO: Listener address to use: ::1
2024-09-12T09:14:06+0800(1): INFO: =====================================================
2024-09-12T09:14:06+0800(1): INFO: Total: 2 'real' addresses discovered
2024-09-12T09:14:06+0800(1): INFO: =====================================================
2024-09-12T09:14:06+0800(1): WARNING: NO EXPLICIT RELAY ADDRESS(ES) ARE CONFIGURED
2024-09-12T09:14:06+0800(1): INFO: ===========Discovering relay addresses: =============
2024-09-12T09:14:06+0800(1): INFO: Relay address to use: 172.19.0.4
2024-09-12T09:14:06+0800(1): INFO: Relay address to use: 172.20.0.3
2024-09-12T09:14:06+0800(1): INFO: Relay address to use: ::1
2024-09-12T09:14:06+0800(1): INFO: =====================================================
2024-09-12T09:14:06+0800(1): INFO: Total: 3 relay addresses discovered
2024-09-12T09:14:06+0800(1): INFO: =====================================================
2024-09-12T09:14:06+0800(1): INFO: pid file created: /var/tmp/turnserver.pid
2024-09-12T09:14:06+0800(1): INFO: IO method: epoll (with changelist)
2024-09-12T09:14:06+0800(1): INFO: Redis DB async connection to be used: ip=redis dbname=2 password= port=6379 connect_timeout=30
2024-09-12T09:14:06+0800(1): WARNING: STUN CHANGE_REQUEST not supported: only one IP address is provided
2024-09-12T09:14:06+0800(1): INFO: Wait for relay ports initialization...
2024-09-12T09:14:06+0800(1): INFO:   relay 172.19.0.4 initialization...
2024-09-12T09:14:06+0800(1): INFO:   relay 172.19.0.4 initialization done
2024-09-12T09:14:06+0800(1): INFO:   relay 172.20.0.3 initialization...
2024-09-12T09:14:06+0800(1): INFO:   relay 172.20.0.3 initialization done
2024-09-12T09:14:06+0800(1): INFO:   relay ::1 initialization...
2024-09-12T09:14:06+0800(1): INFO:   relay ::1 initialization done
2024-09-12T09:14:06+0800(1): INFO: Relay ports initialization done
2024-09-12T09:14:06+0800(26): DEBUG: turn server id=0 created
2024-09-12T09:14:06+0800(26): INFO: IPv4. TCP listener opened on : 127.0.0.1:49100
2024-09-12T09:14:06+0800(26): INFO: IPv4. TCP listener opened on : 172.19.0.4:49100
2024-09-12T09:14:06+0800(26): INFO: IPv4. TCP listener opened on : 172.20.0.3:49100
2024-09-12T09:14:06+0800(26): INFO: IPv6. TCP listener opened on : ::1:49100
2024-09-12T09:14:06+0800(31): DEBUG: turn server id=5 created
2024-09-12T09:14:06+0800(30): DEBUG: turn server id=4 created
2024-09-12T09:14:06+0800(27): DEBUG: turn server id=1 created
2024-09-12T09:14:06+0800(30): INFO: IPv4. TCP listener opened on : 127.0.0.1:49100
2024-09-12T09:14:06+0800(31): INFO: IPv4. TCP listener opened on : 127.0.0.1:49100
2024-09-12T09:14:06+0800(27): INFO: IPv4. TCP listener opened on : 127.0.0.1:49100
2024-09-12T09:14:06+0800(29): DEBUG: turn server id=3 created
2024-09-12T09:14:06+0800(31): INFO: IPv4. TCP listener opened on : 172.19.0.4:49100
2024-09-12T09:14:06+0800(30): INFO: IPv4. TCP listener opened on : 172.19.0.4:49100
2024-09-12T09:14:06+0800(31): INFO: IPv4. TCP listener opened on : 172.20.0.3:49100
2024-09-12T09:14:06+0800(29): INFO: IPv4. TCP listener opened on : 127.0.0.1:49100
2024-09-12T09:14:06+0800(28): DEBUG: turn server id=2 created
2024-09-12T09:14:06+0800(29): INFO: IPv4. TCP listener opened on : 172.19.0.4:49100
2024-09-12T09:14:06+0800(31): INFO: IPv6. TCP listener opened on : ::1:49100
2024-09-12T09:14:06+0800(30): INFO: IPv4. TCP listener opened on : 172.20.0.3:49100
2024-09-12T09:14:06+0800(28): INFO: IPv4. TCP listener opened on : 127.0.0.1:49100
2024-09-12T09:14:06+0800(29): INFO: IPv4. TCP listener opened on : 172.20.0.3:49100
2024-09-12T09:14:06+0800(27): INFO: IPv4. TCP listener opened on : 172.19.0.4:49100
2024-09-12T09:14:06+0800(29): INFO: IPv6. TCP listener opened on : ::1:49100
2024-09-12T09:14:06+0800(30): INFO: IPv6. TCP listener opened on : ::1:49100
2024-09-12T09:14:06+0800(27): INFO: IPv4. TCP listener opened on : 172.20.0.3:49100
2024-09-12T09:14:06+0800(28): INFO: IPv4. TCP listener opened on : 172.19.0.4:49100
2024-09-12T09:14:06+0800(27): INFO: IPv6. TCP listener opened on : ::1:49100
2024-09-12T09:14:06+0800(28): INFO: IPv4. TCP listener opened on : 172.20.0.3:49100
2024-09-12T09:14:06+0800(28): INFO: IPv6. TCP listener opened on : ::1:49100
2024-09-12T09:14:06+0800(32): DEBUG: turn server id=6 created
2024-09-12T09:14:06+0800(32): INFO: IPv4. TCP listener opened on : 127.0.0.1:49100
2024-09-12T09:14:06+0800(1): INFO: Total General servers: 16
2024-09-12T09:14:06+0800(32): INFO: IPv4. TCP listener opened on : 172.19.0.4:49100
2024-09-12T09:14:06+0800(32): INFO: IPv4. TCP listener opened on : 172.20.0.3:49100
2024-09-12T09:14:06+0800(32): INFO: IPv6. TCP listener opened on : ::1:49100
2024-09-12T09:14:06+0800(36): DEBUG: turn server id=10 created
2024-09-12T09:14:06+0800(33): DEBUG: turn server id=7 created
2024-09-12T09:14:06+0800(35): DEBUG: turn server id=9 created
2024-09-12T09:14:06+0800(36): INFO: IPv4. TCP listener opened on : 127.0.0.1:49100
2024-09-12T09:14:06+0800(35): INFO: IPv4. TCP listener opened on : 127.0.0.1:49100
2024-09-12T09:14:06+0800(34): DEBUG: turn server id=8 created
2024-09-12T09:14:06+0800(35): INFO: IPv4. TCP listener opened on : 172.19.0.4:49100
2024-09-12T09:14:06+0800(33): INFO: IPv4. TCP listener opened on : 127.0.0.1:49100
2024-09-12T09:14:06+0800(35): INFO: IPv4. TCP listener opened on : 172.20.0.3:49100
2024-09-12T09:14:06+0800(36): INFO: IPv4. TCP listener opened on : 172.19.0.4:49100
2024-09-12T09:14:06+0800(33): INFO: IPv4. TCP listener opened on : 172.19.0.4:49100
2024-09-12T09:14:06+0800(36): INFO: IPv4. TCP listener opened on : 172.20.0.3:49100
2024-09-12T09:14:06+0800(33): INFO: IPv4. TCP listener opened on : 172.20.0.3:49100
2024-09-12T09:14:06+0800(35): INFO: IPv6. TCP listener opened on : ::1:49100
2024-09-12T09:14:06+0800(36): INFO: IPv6. TCP listener opened on : ::1:49100
2024-09-12T09:14:06+0800(34): INFO: IPv4. TCP listener opened on : 127.0.0.1:49100
2024-09-12T09:14:06+0800(37): DEBUG: turn server id=11 created
2024-09-12T09:14:06+0800(38): DEBUG: turn server id=12 created
2024-09-12T09:14:06+0800(34): INFO: IPv4. TCP listener opened on : 172.19.0.4:49100
2024-09-12T09:14:06+0800(37): INFO: IPv4. TCP listener opened on : 127.0.0.1:49100
2024-09-12T09:14:06+0800(33): INFO: IPv6. TCP listener opened on : ::1:49100
2024-09-12T09:14:06+0800(38): INFO: IPv4. TCP listener opened on : 127.0.0.1:49100
2024-09-12T09:14:06+0800(34): INFO: IPv4. TCP listener opened on : 172.20.0.3:49100
2024-09-12T09:14:06+0800(38): INFO: IPv4. TCP listener opened on : 172.19.0.4:49100
2024-09-12T09:14:06+0800(37): INFO: IPv4. TCP listener opened on : 172.19.0.4:49100
2024-09-12T09:14:06+0800(38): INFO: IPv4. TCP listener opened on : 172.20.0.3:49100
2024-09-12T09:14:06+0800(39): DEBUG: turn server id=13 created
2024-09-12T09:14:06+0800(37): INFO: IPv4. TCP listener opened on : 172.20.0.3:49100
2024-09-12T09:14:06+0800(34): INFO: IPv6. TCP listener opened on : ::1:49100
2024-09-12T09:14:06+0800(38): INFO: IPv6. TCP listener opened on : ::1:49100
2024-09-12T09:14:06+0800(37): INFO: IPv6. TCP listener opened on : ::1:49100
2024-09-12T09:14:06+0800(39): INFO: IPv4. TCP listener opened on : 127.0.0.1:49100
2024-09-12T09:14:06+0800(40): DEBUG: turn server id=14 created
2024-09-12T09:14:06+0800(41): DEBUG: turn server id=15 created
2024-09-12T09:14:06+0800(1): INFO: IPv4. UDP listener opened on: 127.0.0.1:49100
2024-09-12T09:14:06+0800(40): INFO: IPv4. TCP listener opened on : 127.0.0.1:49100
2024-09-12T09:14:06+0800(41): INFO: IPv4. TCP listener opened on : 127.0.0.1:49100
2024-09-12T09:14:06+0800(39): INFO: IPv4. TCP listener opened on : 172.19.0.4:49100
2024-09-12T09:14:06+0800(40): INFO: IPv4. TCP listener opened on : 172.19.0.4:49100
2024-09-12T09:14:06+0800(41): INFO: IPv4. TCP listener opened on : 172.19.0.4:49100
2024-09-12T09:14:06+0800(40): INFO: IPv4. TCP listener opened on : 172.20.0.3:49100
2024-09-12T09:14:06+0800(39): INFO: IPv4. TCP listener opened on : 172.20.0.3:49100
2024-09-12T09:14:06+0800(41): INFO: IPv4. TCP listener opened on : 172.20.0.3:49100
2024-09-12T09:14:06+0800(40): INFO: IPv6. TCP listener opened on : ::1:49100
2024-09-12T09:14:06+0800(39): INFO: IPv6. TCP listener opened on : ::1:49100
2024-09-12T09:14:06+0800(41): INFO: IPv6. TCP listener opened on : ::1:49100
2024-09-12T09:14:06+0800(1): INFO: IPv4. UDP listener opened on: 172.19.0.4:49100
2024-09-12T09:14:06+0800(1): INFO: IPv4. UDP listener opened on: 172.20.0.3:49100
2024-09-12T09:14:06+0800(1): INFO: IPv6. UDP listener opened on: ::1:49100
2024-09-12T09:14:06+0800(1): INFO: Total auth threads: 9
2024-09-12T09:14:06+0800(51): INFO: IPv4. CLI listener opened on : 0.0.0.0:5766
2024-09-12T09:14:06+0800(1): INFO: prometheus collector disabled, not started
2024-09-12T09:14:07+0800(51): INFO: IPv4. CLI connected to: 172.19.0.3:56860
2024-09-12T09:14:07+0800(51): INFO: IPv4. CLI authentication success: 172.19.0.3:56860
2024-09-12T09:14:37+0800(28): INFO: session 002000000000000001: realm <testrealm> user <>: incoming packet message processed, error 401: Unauthorized
2024-09-12T09:14:37+0800(28): INFO: IPv4. Local relay addr: 172.20.0.3:49120
2024-09-12T09:14:37+0800(28): INFO: session 002000000000000001: new, realm=<testrealm>, username=<1726132777:testuser>, lifetime=600
2024-09-12T09:14:37+0800(28): INFO: session 002000000000000001: realm <testrealm> user <1726132777:testuser>: incoming packet ALLOCATE processed, success
2024-09-12T09:14:37+0800(28): INFO: Session 002000000000000001 to be forcefully canceled
2024-09-12T09:14:37+0800(28): INFO: session 002000000000000001: usage: realm=<testrealm>, username=<1726132777:testuser>, rp=3, rb=176, sp=3, sb=304
2024-09-12T09:14:37+0800(28): INFO: session 002000000000000001: peer usage: realm=<testrealm>, username=<1726132777:testuser>, rp=0, rb=0, sp=0, sb=0
2024-09-12T09:14:37+0800(28): INFO: session 002000000000000001: closed (2nd stage), user <1726132777:testuser> realm <testrealm> origin <>, local 172.20.0.3:49100, remote 125.*.*.*:58976, reason: Forceful shutdown
2024-09-12T09:14:37+0800(28): INFO: session 002000000000000001: delete: realm=<testrealm>, username=<1726132777:testuser>
2024-09-12T09:14:37+0800(28): INFO: session 002000000000000002: realm <testrealm> user <1726132777:testuser>: incoming packet message processed, error 438: Wrong nonce
2024-09-12T09:14:37+0800(28): INFO: session 002000000000000002: realm <testrealm> user <1726132777:testuser>: incoming packet CREATE_PERMISSION processed, success
2024-09-12T09:14:37+0800(28): INFO: session 002000000000000002: realm <testrealm> user <1726132777:testuser>: incoming packet message processed, error 400: Bad Request
2024-09-12T09:14:37+0800(28): INFO: session 002000000000000002: realm <testrealm> user <1726132777:testuser>: incoming packet REFRESH processed, error 437: Invalid allocation
2024-09-12T09:14:37+0800(28): INFO: session 002000000000000002: realm <testrealm> user <1726132777:testuser>: incoming packet message processed, error 437: Invalid allocation
2024-09-12T09:15:31+0800(33): INFO: session 007000000000000001: realm <testrealm> user <>: incoming packet message processed, error 401: Unauthorized
2024-09-12T09:15:31+0800(33): INFO: IPv4. Local relay addr: 172.20.0.3:49196
2024-09-12T09:15:31+0800(33): INFO: session 007000000000000001: new, realm=<testrealm>, username=<1726132831:testuser>, lifetime=600
2024-09-12T09:15:31+0800(33): INFO: session 007000000000000001: realm <testrealm> user <1726132831:testuser>: incoming packet ALLOCATE processed, success
2024-09-12T09:15:32+0800(33): INFO: Session 007000000000000001 to be forcefully canceled
2024-09-12T09:15:32+0800(33): INFO: session 007000000000000001: usage: realm=<testrealm>, username=<1726132831:testuser>, rp=3, rb=176, sp=3, sb=304
2024-09-12T09:15:32+0800(33): INFO: session 007000000000000001: peer usage: realm=<testrealm>, username=<1726132831:testuser>, rp=0, rb=0, sp=0, sb=0
2024-09-12T09:15:32+0800(33): INFO: session 007000000000000001: closed (2nd stage), user <1726132831:testuser> realm <testrealm> origin <>, local 172.20.0.3:49100, remote 125.*.*.*:40123, reason: Forceful shutdown
2024-09-12T09:15:32+0800(33): INFO: session 007000000000000001: delete: realm=<testrealm>, username=<1726132831:testuser>
2024-09-12T09:15:32+0800(33): INFO: session 007000000000000002: realm <testrealm> user <1726132831:testuser>: incoming packet message processed, error 438: Wrong nonce
2024-09-12T09:15:32+0800(33): INFO: session 007000000000000002: realm <testrealm> user <1726132831:testuser>: incoming packet CREATE_PERMISSION processed, success
2024-09-12T09:15:32+0800(33): INFO: session 007000000000000002: realm <testrealm> user <1726132831:testuser>: incoming packet message processed, error 400: Bad Request
2024-09-12T09:15:32+0800(33): INFO: session 007000000000000002: realm <testrealm> user <1726132831:testuser>: incoming packet REFRESH processed, error 437: Invalid allocation
2024-09-12T09:15:32+0800(33): INFO: session 007000000000000002: realm <testrealm> user <1726132831:testuser>: incoming packet message processed, error 437: Invalid allocation
2024-09-12T09:15:37+0800(28): INFO: session 002000000000000002: usage: realm=<testrealm>, username=<1726132777:testuser>, rp=3, rb=368, sp=3, sb=308
2024-09-12T09:15:37+0800(28): INFO: session 002000000000000002: peer usage: realm=<testrealm>, username=<1726132777:testuser>, rp=0, rb=0, sp=0, sb=0
2024-09-12T09:15:37+0800(28): INFO: session 002000000000000002: closed (2nd stage), user <1726132777:testuser> realm <testrealm> origin <>, local 172.20.0.3:49100, remote 125.*.*.*:58976, reason: allocation watchdog determined stale session state
2024-09-12T09:16:32+0800(33): INFO: session 007000000000000002: usage: realm=<testrealm>, username=<1726132831:testuser>, rp=3, rb=368, sp=3, sb=308
2024-09-12T09:16:32+0800(33): INFO: session 007000000000000002: peer usage: realm=<testrealm>, username=<1726132831:testuser>, rp=0, rb=0, sp=0, sb=0
2024-09-12T09:16:32+0800(33): INFO: session 007000000000000002: closed (2nd stage), user <1726132831:testuser> realm <testrealm> origin <>, local 172.20.0.3:49100, remote 125.*.*.*:40123, reason: allocation watchdog determined stale session state
zwikst commented 2 months ago

Please ignore it currently. I'll check it carefully again.