[asterisk-dev] Strange aor/endpoint behavior on 13.32
Silvan Nagl
mail at 53c70r.de
Thu Apr 9 06:52:54 CDT 2020
Hi,
recently i upgraded my setup from Asterisk 13.21 to 13.29 and noticed
some strange behavior related to Asterisks internal states. I never had
problems like this before (same problem occurs on 13.32);
First i added the new endpoint '7777':
2020-04-09T11:02:05.000586Z 124 Execute REPLACE INTO ps_aors (
id,
max_contacts,
remove_existing,
qualify_frequency
)
VALUES ('7777', '1', 'yes', '60')
2020-04-09T11:02:05.001362Z 124 Execute REPLACE INTO ps_auths
(id, auth_type, md5_cred, password, realm, username)
VALUES ('7777', 'userpass', NULL, 'a05RAGsBUbjL0fws', NULL,
'7777')
2020-04-09T11:02:05.002705Z 124 Execute REPLACE INTO ps_endpoints (
id,
allow,
aors,
auth,
callerid,
context,
direct_media,
disable_direct_media_on_nat,
disallow,
dtmf_mode,
force_rport,
from_domain,
from_user,
ice_support,
language,
mailboxes,
media_encryption,
media_encryption_optimistic,
outbound_auth,
rewrite_contact,
rtp_symmetric,
send_pai,
send_rpid,
set_var,
transport,
trust_id_inbound,
trust_id_outbound
)
VALUES ('7777', 'alaw', '7777', '7777', NULL,
'from-internal-users', 'no', NULL, 'all', 'rfc4733', NULL, NULL, NULL,
NULL, 'en', '7777 at default', NULL, NULL, NULL, NULL, NULL, 'yes', 'no',
NULL, 'udp', 'no', NULL)
After i used Registers to connect my newly added endpoint to the
Asterisk the internal state got messed up;
Endpoint: 1337/1337 Unavailable 0 of inf
InAuth: 1337/1337
Aor: 1337 1
Transport: udp udp 0 0 0.0.0.0:5060
Endpoint: 7777/7777 Not in use 0 of inf
InAuth: 7777/7777
Aor: 7777 1
Contact: 7777/sip:7777 at 10.0.0.101:5060 3588554430 Avail
7.279
Transport: udp udp 0 0 0.0.0.0:5060
Endpoint: 8888/8888 Unavailable 0 of inf
InAuth: 8888/8888
Aor: 8888 1
Transport: udp udp 0 0 0.0.0.0:5060
Endpoint: 950001/950001 Unavailable 0 of inf
InAuth: 950001/950001
Aor: 950001 1
Transport: udp udp 0 0 0.0.0.0:5060
Endpoint: 950002/950002 Unavailable 0 of inf
InAuth: 950002/950002
Aor: 950002 1
Contact: 950002/sip:950002 at 10.0.0.102:5060 09a8bf6699
Avail 7.049
Transport: udp udp 0 0 0.0.0.0:5060
Endpoint: 950003/950003 Unavailable 0 of inf
InAuth: 950003/950003
Aor: 950003 1
Contact: 950003/sip:950003 at 10.0.0.100:5060 a8eec70ece
Avail 8.207
Transport: udp udp 0 0 0.0.0.0:5060
Endpoint: 950004/950004 Unavailable 0 of inf
InAuth: 950004/950004
Aor: 950004 1
Contact: 950004/sip:950004 at 10.0.0.103:5060 47c21f1e25
Avail 12.306
Transport: udp udp 0 0 0.0.0.0:5060
Endpoint: 999999 Unavailable 0 of inf
InAuth: 999999/999999
Aor: 999999 1
Transport: udp udp 0 0 0.0.0.0:5060
Every endpoint now has the state 'Unavailable' but the newly added
Endpoint '7777'.
The Aors Contact information is still correct telling 'Avail'
All hints now look as follow;
1337 at from-internal-u: PJSIP/1337 State:Unavailable
Presence:not_set Watchers 0
*8*00001 at from-intern: PJSIP/999999 State:Unavailable
Presence:not_set Watchers 0
8888 at from-internal-u: PJSIP/8888 State:Unavailable
Presence:not_set Watchers 0
7777 at from-internal-u: PJSIP/7777 State:Idle
Presence:not_set Watchers 0
999999 at from-internal: PJSIP/999999 State:Unavailable
Presence:not_set Watchers 0
When i now try to change states of my endpoints nothing changes at all.
Even when two endpoints are in a working call the internal state still
tells 'Unavailable'
After doing a 'reload res_pjsip.so' Asterisk works fine and the states
are dynamic again;
Endpoint: 1337/1337 Unavailable 0 of inf
InAuth: 1337/1337
Aor: 1337 1
Transport: udp udp 0 0 0.0.0.0:5060
Endpoint: 7777/7777 Not in use 0 of inf
InAuth: 7777/7777
Aor: 7777 1
Contact: 7777/sip:7777 at 10.0.0.101:5060 3588554430 Avail
6.606
Transport: udp udp 0 0 0.0.0.0:5060
Endpoint: 8888/8888 Unavailable 0 of inf
InAuth: 8888/8888
Aor: 8888 1
Transport: udp udp 0 0 0.0.0.0:5060
Endpoint: 950001/950001 Unavailable 0 of inf
InAuth: 950001/950001
Aor: 950001 1
Transport: udp udp 0 0 0.0.0.0:5060
Endpoint: 950002/950002 Not in use 0 of inf
InAuth: 950002/950002
Aor: 950002 1
Contact: 950002/sip:950002 at 10.0.0.102:5060 09a8bf6699
Avail 7.464
Transport: udp udp 0 0 0.0.0.0:5060
Endpoint: 950003/950003 Not in use 0 of inf
InAuth: 950003/950003
Aor: 950003 1
Contact: 950003/sip:950003 at 10.0.0.100:5060 a8eec70ece
Avail 7.548
Transport: udp udp 0 0 0.0.0.0:5060
Endpoint: 950004/950004 Not in use 0 of inf
InAuth: 950004/950004
Aor: 950004 1
Contact: 950004/sip:950004 at 10.0.0.103:5060 47c21f1e25
Avail 8.569
Transport: udp udp 0 0 0.0.0.0:5060
Endpoint: 999999 Unavailable 0 of inf
InAuth: 999999/999999
Aor: 999999 1
Transport: udp udp 0 0 0.0.0.0:5060
I didn't need a reload when i was on Asterisk 13.21.
some interesting lines from debug log (full log attached):
[Apr 9 11:04:00] DEBUG[7082] res_pjsip/pjsip_options.c: Synchronizing
endpoint '1337' with AORs '1337'
[Apr 9 11:04:00] DEBUG[7082] res_pjsip/pjsip_options.c: Filtered AOR
'1337' on endpoint '1337' as we are looking for '7777'
[Apr 9 11:04:00] DEBUG[7082] res_pjsip/pjsip_options.c: Endpoint '1337'
has no AORs feeding it, setting it to offline state as default
[Apr 9 11:04:00] DEBUG[7082] res_pjsip/pjsip_options.c: Synchronizing
endpoint '7777' with AORs '7777'
[Apr 9 11:04:00] DEBUG[7081] res_pjsip/pjsip_options.c: Adding endpoint
compositor '7777' to AOR '7777'
[Apr 9 11:04:00] DEBUG[7082] res_pjsip/pjsip_options.c: Synchronizing
endpoint '8888' with AORs '8888'
[Apr 9 11:04:00] DEBUG[7082] res_pjsip/pjsip_options.c: Filtered AOR
'8888' on endpoint '8888' as we are looking for '7777'
[Apr 9 11:04:00] DEBUG[7082] res_pjsip/pjsip_options.c: Endpoint '8888'
has no AORs feeding it, setting it to offline state as default
[Apr 9 11:04:00] DEBUG[7082] res_pjsip/pjsip_options.c: Synchronizing
endpoint '950001' with AORs '950001'
[Apr 9 11:04:00] DEBUG[7082] res_pjsip/pjsip_options.c: Filtered AOR
'950001' on endpoint '950001' as we are looking for '7777'
[Apr 9 11:04:00] DEBUG[7082] res_pjsip/pjsip_options.c: Endpoint
'950001' has no AORs feeding it, setting it to offline state as default
[Apr 9 11:04:00] DEBUG[7082] res_pjsip/pjsip_options.c: Synchronizing
endpoint '950002' with AORs '950002'
[Apr 9 11:04:00] DEBUG[7082] res_pjsip/pjsip_options.c: Filtered AOR
'950002' on endpoint '950002' as we are looking for '7777'
[Apr 9 11:04:00] DEBUG[7082] res_pjsip/pjsip_options.c: Endpoint
'950002' has no AORs feeding it, setting it to offline state as default
Did something change after Asterisk 13.21 how endpoints should be
added/handled or am i missing some new feature like 'syncing local
endpoint state to database'?
Best Regards,
Silvan
-------------- next part --------------
Event: SuccessfulAuth
Privilege: security,all
EventTV: 2020-04-09T11:04:00.643+0000
Severity: Informational
Service: PJSIP
EventVersion: 1
AccountID: 7777
SessionID: 0_3917826643 at 10.0.0.101
LocalAddress: IPV4/UDP/192.168.122.38/5060
RemoteAddress: IPV4/UDP/10.0.0.101/5060
UsingPassword: 1
[Apr 9 11:04:00] DEBUG[7081] res_config_mysql.c: MySQL RealTime: Connection okay.
[Apr 9 11:04:00] DEBUG[7081] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM ps_domain_aliases WHERE id = '10.0.0.1'
[Apr 9 11:04:00] DEBUG[7081] res_pjsip_registrar.c: Matched id '7777' to aor '7777'
[Apr 9 11:04:00] DEBUG[7081] res_pjsip_registrar.c: Matched aor '7777' by To username
[Apr 9 11:04:00] DEBUG[7081] res_config_mysql.c: MySQL RealTime: Connection okay.
[Apr 9 11:04:00] DEBUG[7081] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM ps_aors_view WHERE id = '7777'
[Apr 9 11:04:00] DEBUG[7081] config.c: extract double from [3.0] in [-inf, inf] gives [3.000000](0)
[Apr 9 11:04:00] DEBUG[7081] config.c: extract uint from [7200] in [0, 4294967295] gives [7200](0)
[Apr 9 11:04:00] DEBUG[7081] config.c: extract uint from [3600] in [0, 4294967295] gives [3600](0)
[Apr 9 11:04:00] DEBUG[7081] config.c: extract uint from [60] in [0, 4294967295] gives [60](0)
[Apr 9 11:04:00] DEBUG[7081] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7081] config.c: extract uint from [1] in [0, 4294967295] gives [1](0)
[Apr 9 11:04:00] DEBUG[7081] config.c: extract uint from [60] in [0, 86400] gives [60](0)
[Apr 9 11:04:00] DEBUG[7081] config.c: extract double from [3.0] in [-inf, inf] gives [3.000000](0)
[Apr 9 11:04:00] DEBUG[7081] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7081] res_config_mysql.c: MySQL RealTime: Connection okay.
[Apr 9 11:04:00] DEBUG[7081] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM ps_aors_view WHERE id = '7777'
[Apr 9 11:04:00] DEBUG[7081] config.c: extract double from [3.0] in [-inf, inf] gives [3.000000](0)
[Apr 9 11:04:00] DEBUG[7081] config.c: extract uint from [7200] in [0, 4294967295] gives [7200](0)
[Apr 9 11:04:00] DEBUG[7081] config.c: extract uint from [3600] in [0, 4294967295] gives [3600](0)
[Apr 9 11:04:00] DEBUG[7081] config.c: extract uint from [60] in [0, 4294967295] gives [60](0)
[Apr 9 11:04:00] DEBUG[7081] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7081] config.c: extract uint from [1] in [0, 4294967295] gives [1](0)
[Apr 9 11:04:00] DEBUG[7081] config.c: extract uint from [60] in [0, 86400] gives [60](0)
[Apr 9 11:04:00] DEBUG[7082] res_config_mysql.c: MySQL RealTime: Connection okay.
[Apr 9 11:04:00] DEBUG[7082] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM ps_aors_view WHERE id = '7777'
[Apr 9 11:04:00] DEBUG[7082] config.c: extract double from [3.0] in [-inf, inf] gives [3.000000](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [7200] in [0, 4294967295] gives [7200](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [3600] in [0, 4294967295] gives [3600](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [60] in [0, 4294967295] gives [60](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [1] in [0, 4294967295] gives [1](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [60] in [0, 86400] gives [60](0)
[Apr 9 11:04:00] DEBUG[7082] res_pjsip/pjsip_options.c: AOR '7777' qualify options have been modified. Synchronize an AOR local state
[Apr 9 11:04:00] DEBUG[7082] res_pjsip/pjsip_options.c: Configuring AOR '7777' with current state of configuration and world
[Apr 9 11:04:00] DEBUG[7082] config.c: extract double from [3.0] in [-inf, inf] gives [3.000000](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract double from [3.000000] in [-inf, inf] gives [3.000000](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [5060] in [0, 4294967295] gives [5060](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [60] in [0, 86400] gives [60](0)
[Apr 9 11:04:00] DEBUG[7082] res_pjsip/pjsip_options.c: AOR '7777' has transitioned from unqualified to qualified, reset available contacts to 0
[Apr 9 11:04:00] DEBUG[7082] res_pjsip/pjsip_options.c: AOR '7777' now has 0 available contacts
[Apr 9 11:04:00] DEBUG[7081] res_config_mysql.c: MySQL RealTime: Connection okay.
[Apr 9 11:04:00] DEBUG[7081] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM ps_transports WHERE id = 'udp'
[Apr 9 11:04:00] DEBUG[7081] res_sorcery_realtime.c: Filtering out realtime field 'scheme' from retrieval
[Apr 9 11:04:00] DEBUG[7081] config.c: extract uint from [1] in [0, 4294967295] gives [1](0)
[Apr 9 11:04:00] DEBUG[7081] config.c: extract uint from [0] in [0, 65535] gives [0](0)
[Apr 9 11:04:00] DEBUG[7081] config.c: extract int from [100] in [1, 2147483647] gives [100](0)
[Apr 9 11:04:00] DEBUG[7081] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7081] config.c: extract uint from [1] in [0, 4294967295] gives [1](0)
[Apr 9 11:04:00] DEBUG[7081] netsock2.c: Splitting '10.0.0.0' into...
[Apr 9 11:04:00] DEBUG[7081] netsock2.c: ...host '10.0.0.0' and port ''.
[Apr 9 11:04:00] DEBUG[7081] acl.c: 10.0.0.0:0/255.0.0.0:0 sense 0 appended to ACL
[Apr 9 11:04:00] DEBUG[7081] netsock2.c: Splitting '192.168.0.0' into...
[Apr 9 11:04:00] DEBUG[7081] netsock2.c: ...host '192.168.0.0' and port ''.
[Apr 9 11:04:00] DEBUG[7081] acl.c: 192.168.0.0:0/255.255.0.0:0 sense 0 appended to ACL
[Apr 9 11:04:00] DEBUG[7081] netsock2.c: Splitting '172.16.0.0' into...
[Apr 9 11:04:00] DEBUG[7081] netsock2.c: ...host '172.16.0.0' and port ''.
[Apr 9 11:04:00] DEBUG[7081] acl.c: 172.16.0.0:0/255.240.0.0:0 sense 0 appended to ACL
[Apr 9 11:04:00] DEBUG[7081] netsock2.c: Splitting '10.0.0.101' into...
[Apr 9 11:04:00] DEBUG[7081] netsock2.c: ...host '10.0.0.101' and port ''.
[Apr 9 11:04:00] DEBUG[7081] res_pjsip_nat.c: Request is being sent to local address, skipping NAT manipulation
[Apr 9 11:04:00] DEBUG[7082] res_config_mysql.c: MySQL RealTime: Connection okay.
[Apr 9 11:04:00] DEBUG[7082] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM ps_endpoints_view WHERE id LIKE '%' ESCAPE '\\' ORDER BY id
[Apr 9 11:04:00] DEBUG[7082] res_sorcery_realtime.c: Filtering out realtime field 'disallow' from retrieval
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [1800] in [0, 4294967295] gives [1800](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [90] in [0, 4294967295] gives [90](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] res_sorcery_realtime.c: Filtering out realtime field 'disallow' from retrieval
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [1800] in [0, 4294967295] gives [1800](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [90] in [0, 4294967295] gives [90](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] res_sorcery_realtime.c: Filtering out realtime field 'disallow' from retrieval
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [1800] in [0, 4294967295] gives [1800](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [90] in [0, 4294967295] gives [90](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] res_sorcery_realtime.c: Filtering out realtime field 'disallow' from retrieval
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [1800] in [0, 4294967295] gives [1800](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [90] in [0, 4294967295] gives [90](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] res_sorcery_realtime.c: Filtering out realtime field 'disallow' from retrieval
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [1800] in [0, 4294967295] gives [1800](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [90] in [0, 4294967295] gives [90](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] res_sorcery_realtime.c: Filtering out realtime field 'disallow' from retrieval
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [1800] in [0, 4294967295] gives [1800](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [90] in [0, 4294967295] gives [90](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] res_sorcery_realtime.c: Filtering out realtime field 'disallow' from retrieval
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [1800] in [0, 4294967295] gives [1800](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [90] in [0, 4294967295] gives [90](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] res_sorcery_realtime.c: Filtering out realtime field 'disallow' from retrieval
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [1800] in [0, 4294967295] gives [1800](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [90] in [0, 4294967295] gives [90](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7082] res_pjsip/pjsip_options.c: Synchronizing endpoint '1337' with AORs '1337'
[Apr 9 11:04:00] DEBUG[7082] res_pjsip/pjsip_options.c: Filtered AOR '1337' on endpoint '1337' as we are looking for '7777'
[Apr 9 11:04:00] DEBUG[7082] res_pjsip/pjsip_options.c: Endpoint '1337' has no AORs feeding it, setting it to offline state as default
[Apr 9 11:04:00] DEBUG[7082] res_pjsip/pjsip_options.c: Synchronizing endpoint '7777' with AORs '7777'
[Apr 9 11:04:00] DEBUG[7081] res_pjsip/pjsip_options.c: Adding endpoint compositor '7777' to AOR '7777'
[Apr 9 11:04:00] DEBUG[7082] res_pjsip/pjsip_options.c: Synchronizing endpoint '8888' with AORs '8888'
[Apr 9 11:04:00] DEBUG[7082] res_pjsip/pjsip_options.c: Filtered AOR '8888' on endpoint '8888' as we are looking for '7777'
[Apr 9 11:04:00] DEBUG[7082] res_pjsip/pjsip_options.c: Endpoint '8888' has no AORs feeding it, setting it to offline state as default
[Apr 9 11:04:00] DEBUG[7082] res_pjsip/pjsip_options.c: Synchronizing endpoint '950001' with AORs '950001'
[Apr 9 11:04:00] DEBUG[7082] res_pjsip/pjsip_options.c: Filtered AOR '950001' on endpoint '950001' as we are looking for '7777'
[Apr 9 11:04:00] DEBUG[7082] res_pjsip/pjsip_options.c: Endpoint '950001' has no AORs feeding it, setting it to offline state as default
[Apr 9 11:04:00] DEBUG[7082] res_pjsip/pjsip_options.c: Synchronizing endpoint '950002' with AORs '950002'
[Apr 9 11:04:00] DEBUG[7082] res_pjsip/pjsip_options.c: Filtered AOR '950002' on endpoint '950002' as we are looking for '7777'
[Apr 9 11:04:00] DEBUG[7082] res_pjsip/pjsip_options.c: Endpoint '950002' has no AORs feeding it, setting it to offline state as default
[Apr 9 11:04:00] DEBUG[7158] manager.c: Examining AMI event:
Event: PeerStatus
Privilege: system,all
ChannelType: PJSIP
Peer: PJSIP/950002
PeerStatus: Unreachable
[Apr 9 11:04:00] DEBUG[7053] devicestate.c: No provider found, checking channel drivers for PJSIP - 950002
[Apr 9 11:04:00] DEBUG[7082] res_pjsip/pjsip_options.c: Synchronizing endpoint '950003' with AORs '950003'
[Apr 9 11:04:00] DEBUG[7082] res_pjsip/pjsip_options.c: Filtered AOR '950003' on endpoint '950003' as we are looking for '7777'
[Apr 9 11:04:00] DEBUG[7082] res_pjsip/pjsip_options.c: Endpoint '950003' has no AORs feeding it, setting it to offline state as default
[Apr 9 11:04:00] DEBUG[7158] manager.c: Examining AMI event:
Event: PeerStatus
Privilege: system,all
ChannelType: PJSIP
Peer: PJSIP/950003
PeerStatus: Unreachable
[Apr 9 11:04:00] DEBUG[7053] res_config_mysql.c: MySQL RealTime: Connection okay.
[Apr 9 11:04:00] DEBUG[7053] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM ps_endpoints_view WHERE id = '950002'
[Apr 9 11:04:00] DEBUG[7082] res_pjsip/pjsip_options.c: Synchronizing endpoint '950004' with AORs '950004'
[Apr 9 11:04:00] DEBUG[7082] res_pjsip/pjsip_options.c: Filtered AOR '950004' on endpoint '950004' as we are looking for '7777'
[Apr 9 11:04:00] DEBUG[7082] res_pjsip/pjsip_options.c: Endpoint '950004' has no AORs feeding it, setting it to offline state as default
[Apr 9 11:04:00] DEBUG[7158] manager.c: Examining AMI event:
Event: PeerStatus
Privilege: system,all
ChannelType: PJSIP
Peer: PJSIP/950004
PeerStatus: Unreachable
[Apr 9 11:04:00] DEBUG[7082] res_pjsip/pjsip_options.c: Synchronizing endpoint '999999' with AORs '999999'
[Apr 9 11:04:00] DEBUG[7082] res_pjsip/pjsip_options.c: Filtered AOR '999999' on endpoint '999999' as we are looking for '7777'
[Apr 9 11:04:00] DEBUG[7082] res_pjsip/pjsip_options.c: Endpoint '999999' has no AORs feeding it, setting it to offline state as default
[Apr 9 11:04:00] DEBUG[7088] res_pjsip_mwi.c: Created unsolicited MWI subscription for endpoint 7777
[Apr 9 11:04:00] DEBUG[7088] stasis.c: Topic 'mwi:all/7777 at default': 0x7f3c2c00d398 created
[Apr 9 11:04:00] DEBUG[7088] res_pjsip_mwi.c: Creating stasis MWI subscription to mailbox 7777 at default for endpoint 7777. Topic: 'mwi:all/7777 at default':0x7f3c2c00d398 2
[Apr 9 11:04:00] DEBUG[7158] manager.c: Examining AMI event:
Event: ContactStatus
Privilege: system,all
URI: sip:7777 at 10.0.0.101:5060
ContactStatus: Created
AOR: 7777
EndpointName: 7777
RoundtripUsec: 0
[Apr 9 11:04:00] DEBUG[7053] res_sorcery_realtime.c: Filtering out realtime field 'disallow' from retrieval
[Apr 9 11:04:00] DEBUG[7053] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7053] config.c: extract uint from [1800] in [0, 4294967295] gives [1800](0)
[Apr 9 11:04:00] DEBUG[7053] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7053] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7053] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7053] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7053] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7053] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7053] config.c: extract uint from [90] in [0, 4294967295] gives [90](0)
[Apr 9 11:04:00] DEBUG[7053] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7053] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7053] devicestate.c: Changing state for PJSIP/950002 - state 5 (Unavailable)
[Apr 9 11:04:00] DEBUG[7053] devicestate.c: No provider found, checking channel drivers for PJSIP - 950003
[Apr 9 11:04:00] DEBUG[7119] app_queue.c: Device 'PJSIP/950002' changed to state '5' (Unavailable) but we don't care because they're not a member of any queue.
[Apr 9 11:04:00] DEBUG[7158] manager.c: Examining AMI event:
Event: DeviceStateChange
Privilege: call,all
Device: PJSIP/950002
State: UNAVAILABLE
[Apr 9 11:04:00] DEBUG[7081] res_config_mysql.c: MySQL RealTime: Connection okay.
[Apr 9 11:04:00] DEBUG[7081] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM ps_endpoints_view WHERE id = '7777'
[Apr 9 11:04:00] DEBUG[7081] res_sorcery_realtime.c: Filtering out realtime field 'disallow' from retrieval
[Apr 9 11:04:00] DEBUG[7081] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7081] config.c: extract uint from [1800] in [0, 4294967295] gives [1800](0)
[Apr 9 11:04:00] DEBUG[7081] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7081] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7081] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7081] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7081] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7081] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7081] config.c: extract uint from [90] in [0, 4294967295] gives [90](0)
[Apr 9 11:04:00] DEBUG[7081] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7081] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7081] res_pjsip_mwi.c: Sending unsolicited MWI NOTIFY to endpoint 7777, new messages: 0, old messages: 0
[Apr 9 11:04:00] DEBUG[7053] res_config_mysql.c: MySQL RealTime: Connection okay.
[Apr 9 11:04:00] DEBUG[7053] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM ps_endpoints_view WHERE id = '950003'
[Apr 9 11:04:00] DEBUG[7053] res_sorcery_realtime.c: Filtering out realtime field 'disallow' from retrieval
[Apr 9 11:04:00] DEBUG[7053] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7053] config.c: extract uint from [1800] in [0, 4294967295] gives [1800](0)
[Apr 9 11:04:00] DEBUG[7053] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7053] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7053] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7053] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7053] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7053] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7053] config.c: extract uint from [90] in [0, 4294967295] gives [90](0)
[Apr 9 11:04:00] DEBUG[7053] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7053] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7053] devicestate.c: Changing state for PJSIP/950003 - state 5 (Unavailable)
[Apr 9 11:04:00] DEBUG[7053] devicestate.c: No provider found, checking channel drivers for PJSIP - 950004
[Apr 9 11:04:00] DEBUG[7119] app_queue.c: Device 'PJSIP/950003' changed to state '5' (Unavailable) but we don't care because they're not a member of any queue.
[Apr 9 11:04:00] DEBUG[7081] res_config_mysql.c: MySQL RealTime: Connection okay.
[Apr 9 11:04:00] DEBUG[7081] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM ps_aors_view WHERE id = '7777'
[Apr 9 11:04:00] DEBUG[7158] manager.c: Examining AMI event:
Event: DeviceStateChange
Privilege: call,all
Device: PJSIP/950003
State: UNAVAILABLE
[Apr 9 11:04:00] DEBUG[7081] config.c: extract double from [3.0] in [-inf, inf] gives [3.000000](0)
[Apr 9 11:04:00] DEBUG[7081] config.c: extract uint from [7200] in [0, 4294967295] gives [7200](0)
[Apr 9 11:04:00] DEBUG[7081] config.c: extract uint from [3600] in [0, 4294967295] gives [3600](0)
[Apr 9 11:04:00] DEBUG[7081] config.c: extract uint from [60] in [0, 4294967295] gives [60](0)
[Apr 9 11:04:00] DEBUG[7081] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7081] config.c: extract uint from [1] in [0, 4294967295] gives [1](0)
[Apr 9 11:04:00] DEBUG[7081] config.c: extract uint from [60] in [0, 86400] gives [60](0)
[Apr 9 11:04:00] DEBUG[7081] config.c: extract double from [3.0] in [-inf, inf] gives [3.000000](0)
[Apr 9 11:04:00] DEBUG[7081] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7081] config.c: extract double from [3.000000] in [-inf, inf] gives [3.000000](0)
[Apr 9 11:04:00] DEBUG[7081] config.c: extract uint from [5060] in [0, 4294967295] gives [5060](0)
[Apr 9 11:04:00] DEBUG[7081] config.c: extract uint from [60] in [0, 86400] gives [60](0)
[Apr 9 11:04:00] DEBUG[7053] res_config_mysql.c: MySQL RealTime: Connection okay.
[Apr 9 11:04:00] DEBUG[7053] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM ps_endpoints_view WHERE id = '950004'
[Apr 9 11:04:00] DEBUG[7053] res_sorcery_realtime.c: Filtering out realtime field 'disallow' from retrieval
[Apr 9 11:04:00] DEBUG[7053] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7053] config.c: extract uint from [1800] in [0, 4294967295] gives [1800](0)
[Apr 9 11:04:00] DEBUG[7053] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7053] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7053] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7053] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7053] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7053] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7053] config.c: extract uint from [90] in [0, 4294967295] gives [90](0)
[Apr 9 11:04:00] DEBUG[7053] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7053] config.c: extract uint from [0] in [0, 4294967295] gives [0](0)
[Apr 9 11:04:00] DEBUG[7053] devicestate.c: Changing state for PJSIP/950004 - state 5 (Unavailable)
[Apr 9 11:04:00] DEBUG[7119] app_queue.c: Device 'PJSIP/950004' changed to state '5' (Unavailable) but we don't care because they're not a member of any queue.
[Apr 9 11:04:00] DEBUG[7158] manager.c: Examining AMI event:
Event: DeviceStateChange
Privilege: call,all
Device: PJSIP/950004
State: UNAVAILABLE
More information about the asterisk-dev
mailing list