SMS Phone From Userstore

Not sure what happened, as this was working, but suddenly it does not. Creating an SMS token and selecting Read number dynamically from user source on each request. an SMS does not send. Checking the logs it says

[WARNING][privacyidea.lib.tokens.smstoken]Token PISMxxx does not have a phone number!
[WARNING][privacyidea.lib.tokens.smstoken]The PIN was correct, but the SMS could not be sent: SMSError(error_id=400, description='SMS could not be sent: 400')

My resolvers are configured to map AD attribute mobile to PI attribute phone. However, I’ve also tested mapping AD telephoneNumber to PI attribute phone and no change in behavior. If I manually define the phone number on token creation an SMS gets sent, verifying my SMS gateway config.

Could it be my LDAP server(s) aren’t responding fast enough and a number isn’t assigned? Is the number only queried and assigned at token creation or every time an auth request comes in?

What else should I be looking at?

This shouldn’t happen suddenly. Increase your loglevel. Look at the tokeninfos of your token.

What do you mean tokeninfos of my token, just the token info screen in the web gui?

Enabled debug logging…the PrivacyIDEA log isn’t nearly as verbose as the apache error logs. Looking at the apache logs, I notice this section…3rd to last line, I separated it with a few blank lines, it says user has no phone of type mobile. Is this saying I’ve configured something to look for a mobile field or is this the mapping function that’s pulling AD attributes and sticking them in PI fields? Looking at the user in PrivacyIDEA, the phone field is populated properly…

[Wed Jun 30 21:29:21.082285 2021] [wsgi:error] [pid 5491:tid 139679409637120] [remote 192.168.1.250:45496] DEBUG:privacyidea.lib.user:Exiting get_username with result ABC123
[Wed Jun 30 21:29:21.082464 2021] [wsgi:error] [pid 5491:tid 139679409637120] [remote 192.168.1.250:45496] DEBUG:privacyidea.lib.user:Entering __init__ with arguments (User(login='', realm='', resolver=''),) and keywords {'login': 'ABC123', 'resolver': 'Users', 'realm': 'contoso'}
[Wed Jun 30 21:29:21.082616 2021] [wsgi:error] [pid 5491:tid 139679409637120] [remote 192.168.1.250:45496] DEBUG:privacyidea.lib.config:Entering get_from_config with arguments ('UserCacheExpiration', '0') and keywords {}
[Wed Jun 30 21:29:21.082769 2021] [wsgi:error] [pid 5491:tid 139679409637120] [remote 192.168.1.250:45496] DEBUG:privacyidea.lib.config:Exiting get_from_config with result 
[Wed Jun 30 21:29:21.082899 2021] [wsgi:error] [pid 5491:tid 139679409637120] [remote 192.168.1.250:45496] INFO:privacyidea.lib.usercache:Non-Integer value stored in system config UserCacheExpiration
[Wed Jun 30 21:29:21.083037 2021] [wsgi:error] [pid 5491:tid 139679409637120] [remote 192.168.1.250:45496] DEBUG:privacyidea.lib.resolver:Entering get_resolver_object with arguments ('Users',) and keywords {}
[Wed Jun 30 21:29:21.083198 2021] [wsgi:error] [pid 5491:tid 139679409637120] [remote 192.168.1.250:45496] DEBUG:privacyidea.lib.resolver:Entering get_resolver_list with arguments () and keywords {'filter_resolver_name': 'Users'}
[Wed Jun 30 21:29:21.083337 2021] [wsgi:error] [pid 5491:tid 139679409637120] [remote 192.168.1.250:45496] DEBUG:privacyidea.lib.resolver:Exiting get_resolver_list with result HIDDEN
[Wed Jun 30 21:29:21.083497 2021] [wsgi:error] [pid 5491:tid 139679409637120] [remote 192.168.1.250:45496] DEBUG:privacyidea.lib.resolver:Exiting get_resolver_object with result <privacyidea.lib.resolvers.LDAPIdResolver.IdResolver object at 0x7f097e50ccf8>
[Wed Jun 30 21:29:21.083646 2021] [wsgi:error] [pid 5491:tid 139679409637120] [remote 192.168.1.250:45496] DEBUG:privacyidea.lib.resolvers.LDAPIdResolver:login name filter: '|(sAMAccountName=ABC123)(mail=ABC123)(userPrincipalName=ABC123)'
[Wed Jun 30 21:29:21.083770 2021] [wsgi:error] [pid 5491:tid 139679409637120] [remote 192.168.1.250:45496] DEBUG:privacyidea.lib.resolvers.LDAPIdResolver:Searching user 'ABC123' in LDAP.
[Wed Jun 30 21:29:21.093097 2021] [wsgi:error] [pid 5491:tid 139679409637120] [remote 192.168.1.250:45496] DEBUG:privacyidea.lib.resolver:Entering get_resolver_list with arguments () and keywords {'filter_resolver_name': 'Users'}
[Wed Jun 30 21:29:21.093269 2021] [wsgi:error] [pid 5491:tid 139679409637120] [remote 192.168.1.250:45496] DEBUG:privacyidea.lib.resolver:Exiting get_resolver_list with result HIDDEN
[Wed Jun 30 21:29:21.093405 2021] [wsgi:error] [pid 5491:tid 139679409637120] [remote 192.168.1.250:45496] DEBUG:privacyidea.lib.user:Exiting __init__ with result None
[Wed Jun 30 21:29:21.093566 2021] [wsgi:error] [pid 5491:tid 139679409637120] [remote 192.168.1.250:45496] DEBUG:privacyidea.lib.user:Entering get_user_phone with arguments (User(login='ABC123', realm='contoso', resolver='Users'), 'mobile') and keywords {}
[Wed Jun 30 21:29:21.093701 2021] [wsgi:error] [pid 5491:tid 139679409637120] [remote 192.168.1.250:45496] DEBUG:privacyidea.lib.resolver:Entering get_resolver_object with arguments ('Users',) and keywords {}
[Wed Jun 30 21:29:21.093842 2021] [wsgi:error] [pid 5491:tid 139679409637120] [remote 192.168.1.250:45496] DEBUG:privacyidea.lib.resolver:Entering get_resolver_list with arguments () and keywords {'filter_resolver_name': 'Users'}
[Wed Jun 30 21:29:21.093977 2021] [wsgi:error] [pid 5491:tid 139679409637120] [remote 192.168.1.250:45496] DEBUG:privacyidea.lib.resolver:Exiting get_resolver_list with result HIDDEN
[Wed Jun 30 21:29:21.094136 2021] [wsgi:error] [pid 5491:tid 139679409637120] [remote 192.168.1.250:45496] DEBUG:privacyidea.lib.resolver:Exiting get_resolver_object with result <privacyidea.lib.resolvers.LDAPIdResolver.IdResolver object at 0x7f097e50ccf8>


[Wed Jun 30 21:29:21.099108 2021] [wsgi:error] [pid 5491:tid 139679409637120] [remote 192.168.1.250:45496] WARNING:privacyidea.lib.user:userobject (User(login='ABC123', realm='contoso', resolver='Users')) has no phone of type 'mobile'.


[Wed Jun 30 21:29:21.099242 2021] [wsgi:error] [pid 5491:tid 139679409637120] [remote 192.168.1.250:45496] DEBUG:privacyidea.lib.user:Exiting get_user_phone with result 
[Wed Jun 30 21:29:21.099372 2021] [wsgi:error] [pid 5491:tid 139679409637120] [remote 192.168.1.250:45496] WARNING:privacyidea.lib.tokens.smstoken:Token PISM0001D4CE does not have a phone number!

As a side-note, I’ve completed upgrading to PrivacyIDEA 3.6 and the issue persists.

Your questions are unanswered:

The mobile number is read from AD on each authentication request. Or read from the usercache if activated.
Thus, it could be that your ldap server is not responding during an auth request. But I think you should see this in the logs.

Do you actually see a mobile number in the user details in privacyIDEA?

I disabled my user cache just to ensure that wasn’t in play, unfortunately that didn’t resolve anything. Yes, PrivacyIDEA sees the phone number when I pull up the user’s details.

The magic happens here:

But it looks like the attribute mapping is wrong, otherwise you would not get the message has no phone of type 'mobile'.

Why don’t you send a screenshot of a user (with attributes) or the attribute mapping of your resolver?

Ya, that log line has me confused because, outside of the LDAP resolver attribute mapping, mobile isn’t referenced anywhere.

image
image

Reading the code there…excuse me if I interpret the logic wrong:

Lines 408-412, If dynamic_phone is true, set phone attribute value to the value of mobile.

So I just changed my LDAP resolver to include:

{
  "phone": "telephoneNumber",
  "mobile": "telephoneNumber"
}

Then testing SMS token set to dynamic and the text went through. So it appears PrivacyIDEA requires the mobile attribute to be mapped for the dynamic phone setting to work properly?

I modified my LDAP resolver to below and tested an SMS token with dynamic_phone not set and it still works properly.

{
  "phone": "telephoneNumber",
  "mobile": "mobile"
}

That is right. This is why the resolver defaults of AD have the mobile attribute.
You were successfully misleading me by claiming, that “suddenly” it stopped working.

Unintentionally misleading…I didn’t recall having the mobile attribute still in there, I thought I removed it when setting up the LDAP resolver…but apparently I did and then I removed it. Maybe a future note in the interface or documentation showing that attribute is required for the dynamic_phone? If it’s already stated…well then I just can’t read, I went over the documentation multiple times.