[Home]

Summary:ASTERISK-28694: res_phoneprov: Phone provision stopped updating with a reload of res_phoneprov
Reporter:Dan (dwsiemens)Labels:
Date Opened:2020-01-15 09:31:15.000-0600Date Closed:2020-01-22 08:30:53.000-0600
Priority:MajorRegression?Yes
Status:Closed/CompleteComponents:Resources/res_phoneprov
Versions:16.7.0 Frequency of
Occurrence		Constant
Related
Issues:
Environment:Redhat 7.7, (current updates) X64, Real time Asterisk Using mysql as DB platform Attachments:( 0) debug-clean.txt
Description:I have tried creating new users  as well as moving a phone to a user,   I reload the phone prov module and the config does not change for the mac address,

The config remains as what the server started (booted) with.    

Stopped working when upgrading from 16.6.2 to 16.7.0

Comments:By: Asterisk Team (asteriskteam) 2020-01-15 09:31:16.427-0600

Thanks for creating a report! The issue has entered the triage process. That means the issue will wait in this status until a Bug Marshal has an opportunity to review the issue. Once the issue has been reviewed you will receive comments regarding the next steps towards resolution.

A good first step is for you to review the [Asterisk Issue Guidelines|https://wiki.asterisk.org/wiki/display/AST/Asterisk+Issue+Guidelines] if you haven't already. The guidelines detail what is expected from an Asterisk issue report.

Then, if you are submitting a patch, please review the [Patch Contribution Process|https://wiki.asterisk.org/wiki/display/AST/Patch+Contribution+Process].

Please note that once your issue enters an open state it has been accepted. As Asterisk is an open source project there is no guarantee or timeframe on when your issue will be looked into. If you need expedient resolution you will need to find and pay a suitable developer. Asking for an update on your issue will not yield any progress on it and will not result in a response. All updates are posted to the issue when they occur.
By: Joshua C. Colp (jcolp) 2020-01-15 12:28:52.278-0600

Is anything output on the console when you issue the reload? Do you have an example config file?
By: Dan (dwsiemens) 2020-01-16 07:30:00.793-0600

console output

vmctel22*CLI> module reload res_phoneprov.so  
Module 'res_phoneprov.so' reloaded successfully.
   -- Reloading module 'res_phoneprov.so' (HTTP Phone Provisioning)

from users.conf   (note I'm realtime so its in a database table I pulled out the fields and it should look like this.    Keep in mind this worked up to 16.6.2  it only stopped when I updated to 16.7.0

[patricia-user]
autoprov=yes
cid_number=33491
fullname=Patricia User
label=33491
linekeys=2
linenumber=1
macaddress=00004f234ca1f
secret=81828283287282
timezone=America/Chicago
username=Patricia-User
profile=Legacy








By: Joshua C. Colp (jcolp) 2020-01-16 07:37:39.075-0600

In the future please ensure you state in the description that it worked in a previous version.
By: Dan (dwsiemens) 2020-01-16 21:46:47.949-0600

I've upgraded the severity because the changes aren't picked up on restart so there doesn't appear to be a workaround.


By: Sean Bright (seanbright) 2020-01-17 08:19:09.771-0600

Two things:

# Can you grab the console output again but with debug logging enabled?
# Can you attach your {{extconfig.conf}}?
By: Dan (dwsiemens) 2020-01-17 08:39:07.157-0600

asterisk]# cat /etc/asterisk/extconfig.conf
;
; Static and realtime external configuration
; engine configuration
;
; See https://wiki.asterisk.org/wiki/display/AST/Realtime+Database+Configuration
; for basic table formatting information.
;

[settings]
;
; static realtime
;
ais.conf => odbc,configuration,options
amd.conf => odbc,configuration,options
ccss.conf => odbc,configuration,options
cdr.conf => odbc,configuration,options
cdr_manager.conf => odbc,configuration,options
chan_dahdi.conf => odbc,configuration,options
cli.conf => odbc,configuration,options
cli_aliases.conf => odbc,configuration,options
codecs.conf => odbc,configuration,options
extensions.conf => odbc,configuration,options
followme.conf => odbc,configuration,options
func_odbc.conf => odbc,configuration,options
http.conf => odbc,configuration,options
iax.conf => odbc,configuration,options
iaxprov.conf => odbc,configuration,options
indications.conf => odbc,configuration,options  
manager.conf => odbc,configuration,options
meetme.conf => odbc,configuration,options
musiconhold.conf => odbc,configuration,options
phoneprov.conf => odbc,configuration,options
privacy.conf => odbc,configuration,options
queuerules.conf => odbc,configuration,options
queues.conf => odbc,configuration,options
rtp.conf => odbc,configuration,options
sip.conf => odbc,configuration,options
sip_notify.conf => odbc,configuration,options
udptl.conf => odbc,configuration,options
users.conf => odbc,configuration,options
voicemail.conf => odbc,configuration,options
cel.conf => odbc,configuration,options
cel_odbc.conf => odbc,configuration,options
res_snmp.conf => odbc,configuration,options
features.conf => odbc,configuration,features
pjsip.conf =>odbc,configuration,pjsip

;
; dynamic realtime
;
extensions => odbc,configuration,extensions
iaxpeers => odbc,configuration,iaxendpoints
iaxusers => odbc,configuration,iaxendpoints    
meetme => odbc,configuration,conferences  
queues => odbc,configuration,queues
queue_log => odbc,logging,queue_log
queue_members => odbc,configuration,queue_member_table
sippeers => odbc,configuration,sipendpoints ;Should avoid
sipusers => odbc,configuration,sipendpoints ;Should avoid
voicemail => odbc,configuration,voicemailboxes


;[settings]
;
; Static configuration files:
;
; file.conf => driver,database[,table[,priority]]
;
; maps a particular configuration file to the given
; database driver, database and table (or uses the
; name of the file as the table if not specified)
;
; Uncomment to load queues.conf via the odbc engine.
;
;queues.conf => odbc,asterisk,ast_config
;extensions.conf => sqlite,asterisk,ast_config
;
; The following files CANNOT be loaded from Realtime storage:
;       asterisk.conf
;       extconfig.conf (this file)
;       logger.conf
;
; Additionally, the following files cannot be loaded from
; Realtime storage unless the storage driver is loaded
; early using 'preload' statements in modules.conf:
;       manager.conf
;       cdr.conf
;       rtp.conf
;
; Named ACLs specified in realtime also can not be used
; from manager.conf unless the storage driver is preloaded.
; Attempting to use a realtime stored named ACL before the
; driver is loaded will result in an invalid ACL which
; rejects all addresses.
;
; Realtime configuration engine
;
; maps a particular family of realtime
; configuration to a given database driver,
; database and table (or uses the name of
; the family if the table is not specified
;
;example => odbc,asterisk,alttable,1
;example => mysql,asterisk,alttable,2
;example2 => ldap,"dc=oxymium,dc=net",example2
;
; Additionally, priorities are now supported for use as failover methods
; for retrieving realtime data.  If one connection fails to retrieve any
; information, the next sequential priority will be tried next.  This
; especially works well with ODBC connections, since res_odbc now caches
; when connection failures occur and prevents immediately retrying those
; connections until after a specified timeout.  Note:  priorities must
; start at 1 and be sequential (i.e. if you have only priorities 1, 2,
; and 4, then 4 will be ignored, because there is no 3).
;
;
; Possible driver backends:
;
; "odbc" is shown in the examples below, but is not the only valid realtime
; engine.  Here are several of the possible options:
;    odbc ... res_config_odbc
;    sqlite ... res_config_sqlite
;    sqlite3 ... res_config_sqlite3
;    pgsql ... res_config_pgsql
;    curl ... res_config_curl
;    ldap ... res_config_ldap
;    mysql ... res_config_mysql (available via add-ons in menuselect)
;
; Note: The res_config_pgsql and res_config_sqlite backends configure the
; database used in their respective configuration files and ignore the
; database name configured in this file.
;
;iaxusers => odbc,asterisk
;iaxpeers => odbc,asterisk
;sippeers => odbc,asterisk
;sipregs => odbc,asterisk ; (avoid sipregs if possible, e.g. by using a view)
;ps_endpoints => odbc,asterisk
;ps_auths => odbc,asterisk
;ps_aors => odbc,asterisk
;ps_domain_aliases => odbc,asterisk
;ps_endpoint_id_ips => odbc,asterisk
;ps_outbound_publishes => odbc,asterisk
;ps_inbound_publications = odbc,asterisk
;ps_asterisk_publications = odbc,asterisk
;voicemail => odbc,asterisk
;extensions => odbc,asterisk
;meetme => mysql,general
;queues => odbc,asterisk
;queue_members => odbc,asterisk
;queue_rules => odbc,asterisk
;acls => odbc,asterisk
;musiconhold => mysql,general
;queue_log => mysql,general
;
;
; While most dynamic realtime engines are automatically used when defined in
; this file, 'extensions', distinctively, is not.  To activate dynamic realtime
; extensions, you must turn them on in each respective context within
; extensions.conf with a switch statement.  The syntax is:
;      switch => Realtime/[[db_context@]tablename]/<opts>
; The only option available currently is the 'p' option, which disallows
; extension pattern queries to the database.  If you have no patterns defined
; in a particular context, this will save quite a bit of CPU time.  However,
; note that using dynamic realtime extensions is not recommended anymore as a
; best practice; instead, you should consider writing a static dialplan with
; proper data abstraction via a tool like func_odbc.
By: Dan (dwsiemens) 2020-01-17 08:40:27.705-0600

mctel22*CLI> module reload res_phoneprov.so
Module 'res_phoneprov.so' reloaded successfully.
   -- Reloading module 'res_phoneprov.so' (HTTP Phone Provisioning)
[2020-01-17 08:39:52.482] WARNING[34708]: logger: ***: Log queue threshold (1000) exceeded.  Discarding new messages.
[2020-01-17 08:39:52.485] WARNING[111602]: logger: ***: Logging resumed.  1422 messages discarded.
[2020-01-17 08:39:52.486] ERROR[34708]: res_phoneprov.c:1665 ast_phoneprov_add_extension: Could not look up profile 'jbazibuhe' - skipping.
[2020-01-17 08:39:52.494] WARNING[34708]: logger: ***: Log queue threshold (1000) exceeded.  Discarding new messages.
[2020-01-17 08:39:52.495] WARNING[111602]: logger: ***: Logging resumed.  580 messages discarded.
[2020-01-17 08:39:52.500] ERROR[34708]: res_phoneprov.c:1665 ast_phoneprov_add_extension: Could not look up profile 'hdelvalle' - skipping.
[2020-01-17 08:39:52.504] WARNING[34708]: logger: ***: Log queue threshold (1000) exceeded.  Discarding new messages.
[2020-01-17 08:39:52.506] WARNING[111602]: logger: ***: Logging resumed.  1177 messages discarded.
[2020-01-17 08:39:52.513] ERROR[34708]: res_phoneprov.c:1665 ast_phoneprov_add_extension: Could not look up profile 'US-UIUIOP2' - skipping.
[2020-01-17 08:39:52.518] WARNING[34708]: logger: ***: Log queue threshold (1000) exceeded.  Discarding new messages.
[2020-01-17 08:39:52.526] WARNING[111602]: logger: ***: Logging resumed.  5316 messages discarded.
[2020-01-17 08:39:52.577] WARNING[34708]: logger: ***: Log queue threshold (1000) exceeded.  Discarding new messages.
[2020-01-17 08:39:52.581] WARNING[111602]: logger: ***: Logging resumed.  2600 messages discarded.



By: Dan (dwsiemens) 2020-01-17 08:42:13.669-0600

in debug log
[root@vmctel22 asterisk]# less debug |grep phonepr
[2020-01-17 08:39:32.379] DEBUG[34708] res_sorcery_config.c: Using bucket size of '1' for objects of type 'phoneprov' from 'pjsip.conf'
[2020-01-17 08:39:32.379] DEBUG[34708] res_pjsip_config_wizard.c: Config file 'pjsip_wizard.conf' was unchanged for 'phoneprov'.
Module: res_phoneprov.so


By: Sean Bright (seanbright) 2020-01-17 08:44:30.753-0600

Don't grep for phonepr. Just attach the debug file to this issue as an attachment, not pasted in a comment.
By: Dan (dwsiemens) 2020-01-17 08:50:38.149-0600

This is the debug log file
By: Sean Bright (seanbright) 2020-01-17 09:23:26.032-0600

Given the complexity of your environment I don't think it is feasible for one of us to try and set up a reproducing environment. If you are willing and able to do a [{{git bisect}}|https://git-scm.com/docs/git-bisect] between the 16.6.2 and 16.7.0 tags to find the commit that broke this, that would make it much more likely that this would be addressed sooner than later.
By: Dan (dwsiemens) 2020-01-17 09:25:56.107-0600

how would I do that?    

By: Sean Bright (seanbright) 2020-01-17 09:29:13.795-0600

You use the [{{git bisect}}|https://git-scm.com/docs/git-bisect] command. If you aren't familiar with {{git}} or bisects in general than it is probably a dead end.
By: Dan (dwsiemens) 2020-01-17 09:32:28.098-0600

I'm not a git user    

so what do you need to reproduce the issue?

By: Dan (dwsiemens) 2020-01-17 09:51:26.503-0600

Or i can likely setup a test environment and have you do a screen share session.  

By: Sean Bright (seanbright) 2020-01-17 10:19:49.987-0600

So a git bisect involves iteratively building and testing various versions of Asterisk between a known good (16.6.2) version and a known bad one (16.7.0). If you can set up a test environment that is certainly something we can try.
By: Dan (dwsiemens) 2020-01-17 10:26:21.107-0600

Ok  I'll see what I can replicate here.  and when I'm ready I can send you a zoom session and I can give you control if needed.  

By: Sean Bright (seanbright) 2020-01-17 10:26:45.125-0600

Sounds good.
By: Sean Bright (seanbright) 2020-01-17 10:34:35.967-0600

Attached a [redacted debug log|^debug-clean.txt] which replaces all MAC addresses with {{000000abcdef}} and trims out everything else.
By: Dan (dwsiemens) 2020-01-21 07:53:25.499-0600

After the event yesterday I have the recent provisioning records. showing up.       No changes have been made other then the restart.  
Could something have loaded different or unloaded differently?  
By: Sean Bright (seanbright) 2020-01-21 07:55:54.699-0600

🤷🏻‍♂️
By: Dan (dwsiemens) 2020-01-21 07:58:32.158-0600

I know,   right  but its a change of behavior from a few days ago.   That doesn't make sense.     Its code,  does the same thing all the time unless the inputs changed.    


By: Dan (dwsiemens) 2020-01-22 08:14:24.365-0600

Its working so this is not a code bug.   Its got to be something that was different on a restart.