I think Digium Phones are having a problem with the new Let’s Encrypt certificate.
This morning I had calls that 2 customer sites were down. My phones were down too.
They all use D60 and D65 phones.
I have no idea if my “old” cert was using the new root or not, but while troubleshooting, I deleted it and re-created the cert. I know the old cert still had ~48 days remaining. Anyways, the new cert is definitely using the new root. Also, strangely, when this all began, it wasn’t October 1st UTC. (It still isn’t).
After doing a bunch of digging through phone syslogs and troubleshooting, I think Digium might not trust the latest LE Root. (Let's Encrypt - Can't generate new cert, ACME v1 EOL per LE)
The phones are throwing errors when trying to access Apps as well as “Invalid SIP TLS Certificate, Error Code: 0x00000004” if they are using SIP-TLS.
He’s an example of the syslog from a D65 trying to make an outbound call:
Sep 30 19:58:43 192.168.42.133 phone: VIEW EVENT: fn.dial
Sep 30 19:58:43 192.168.42.133 phone: LogScreen::process_event: fn.dial
Sep 30 19:58:43 192.168.42.133 phone: LogScreen::process_event() fn.dial new event: fn.dial.0.--redacted-phone-number--.0
Sep 30 19:58:43 192.168.42.133 phone: _call_screen, cl_size:0, updated_call NULL status:0
Sep 30 19:58:43 192.168.42.133 phone: rebuild_call_list, updated_call status: -1, handle: (null)
Sep 30 19:58:43 192.168.42.133 phone: call_list resized to W:296 H:64
Sep 30 19:58:43 192.168.42.133 xyz: KEY 40-[ ( ] 1
Sep 30 19:58:43 192.168.42.133 phone: dbus_hide_idle_apps()
Sep 30 19:58:43 192.168.42.133 phone: _set_top_label()
Sep 30 19:58:43 192.168.42.133 phone: _softkeys()
Sep 30 19:58:43 192.168.42.133 phone: keybuffer_cb()
Sep 30 19:58:43 192.168.42.133 phone: Indicator cb
Sep 30 19:58:43 192.168.42.133 phone: Line 0 update
Sep 30 19:58:43 192.168.42.133 phone: _call_screen, cl_size:0, updated_call NULL status:0
Sep 30 19:58:43 192.168.42.133 phone: rebuild_call_list, updated_call status: -1, handle: (null)
Sep 30 19:58:43 192.168.42.133 phone: call_list resized to W:296 H:64
Sep 30 19:58:43 192.168.42.133 core[988]: core dbus_callback()
Sep 30 19:58:43 192.168.42.133 phone: dbus_hide_idle_apps()
Sep 30 19:58:43 192.168.42.133 phone: _set_top_label()
Sep 30 19:58:43 192.168.42.133 phone: _softkeys()
Sep 30 19:58:43 192.168.42.133 phone: keybuffer_cb()
Sep 30 19:58:43 192.168.42.133 phone: Indicator cb
Sep 30 19:58:43 192.168.42.133 phone: Line 0 update
Sep 30 19:58:43 192.168.42.133 phone: _call_screen, cl_size:0, updated_call NULL status:0
Sep 30 19:58:43 192.168.42.133 phone: rebuild_call_list, updated_call status: -1, handle: (null)
Sep 30 19:58:43 192.168.42.133 phone: call_list resized to W:296 H:64
Sep 30 19:58:43 192.168.42.133 phone: dbus_hide_idle_apps()
Sep 30 19:58:43 192.168.42.133 phone: _set_top_label()
Sep 30 19:58:43 192.168.42.133 phone: _softkeys()
Sep 30 19:58:43 192.168.42.133 phone: dbus_audio_mute(off)
Sep 30 19:58:43 192.168.42.133 phone: new call subslot 0
Sep 30 19:58:43 192.168.42.133 phone: Highest priority, 0 account
Sep 30 19:58:43 192.168.42.133 phone: dbus_audio_set_volume(speakerphone, output, 50)
Sep 30 19:58:43 192.168.42.133 phone: dbus_audio_wire(speakerphone)
Sep 30 19:58:43 192.168.42.133 phone: dbus_make_call(0, --redacted-phone-number--, 0, 0) HANDLE: idle_dial_3
Sep 30 19:58:43 192.168.42.133 phone: Subslot 0
Sep 30 19:58:43 192.168.42.133 core[988]: core dbus_callback()
Sep 30 19:58:43 192.168.42.133 core[988]: callbridge: dus_send_audio_mute_status
Sep 30 19:58:43 192.168.42.133 core[988]: callbridge: dus_send_audio_volume_status
Sep 30 19:58:43 192.168.42.133 core[988]: callbridge: aud_set_call_device speakerphone speakerphone
Sep 30 19:58:43 192.168.42.133 core[988]: callbridge: Already on this device
Sep 30 19:58:43 192.168.42.133 core[988]: callbridge: dus_send_audio_wire_status
Sep 30 19:58:43 192.168.42.133 phone: @@@ new state: phone.idle
Sep 30 19:58:43 192.168.42.133 phone: Indicator cb
Sep 30 19:58:43 192.168.42.133 phone: Line 0 update
Sep 30 19:58:43 192.168.42.133 phone: line_icon_update(0, 7)
Sep 30 19:58:43 192.168.42.133 phone: ACTIVITY 8
Sep 30 19:58:43 192.168.42.133 phone: _call_screen, cl_size:0, updated_call idle_dial_3 status:19
Sep 30 19:58:43 192.168.42.133 phone: rebuild_call_list, updated_call status: 19, handle: idle_dial_3
Sep 30 19:58:43 192.168.42.133 phone: call_list resized to W:296 H:64
Sep 30 19:58:43 192.168.42.133 phone: _call_screen, updated_call idle_dial_3 status:19 number:--redacted-phone-number--
Sep 30 19:58:43 192.168.42.133 phone: dbus_hide_idle_apps()
Sep 30 19:58:43 192.168.42.133 phone: _set_top_label()
Sep 30 19:58:43 192.168.42.133 phone: _softkeys()
Sep 30 19:58:43 192.168.42.133 phone: check_status_data()
Sep 30 19:58:43 192.168.42.133 phone: Loop status line 1
Sep 30 19:58:43 192.168.42.133 core[988]: core dbus_callback()
Sep 30 19:58:43 192.168.42.133 core[988]: callbridge: state_find_accountp_by_slot
Sep 30 19:58:43 192.168.42.133 core[988]: callbridge: 12:58:43.518 pjsua_call.c !Making call with acc #1 to <sip:[email protected]:5061;transport=tls>
Sep 30 19:58:43 192.168.42.133 core[988]: callbridge: 12:58:43.518 src/broadcom_p .pjsua_set_snd_dev no-op
Sep 30 19:58:43 192.168.42.133 core[988]: callbridge: 12:58:43.526 tlsc0x3ab0cc .TLS client transport created
Sep 30 19:58:43 192.168.42.133 core[988]: callbridge: 12:58:43.527 tlsc0x3ab0cc .TLS transport 192.168.42.133:44114 is connecting to voice.--redacted--:5061...
Sep 30 19:58:43 192.168.42.133 core[988]: callbridge: 12:58:43.537 pjsua_media.c .Call 3: initializing media..
Sep 30 19:58:43 192.168.42.133 core[988]: callbridge: 12:58:43.539 pjsua_media.c ..RTP socket reachable at 192.168.42.133:4006
Sep 30 19:58:43 192.168.42.133 core[988]: callbridge: 12:58:43.539 pjsua_media.c ..RTCP socket reachable at 192.168.42.133:4007
Sep 30 19:58:43 192.168.42.133 core[988]: callbridge: 12:58:43.540 pjsua_media.c ..Media index 0 selected for audio call 3
Sep 30 19:58:43 192.168.42.133 core[988]: callbridge: alt_codec_test_alloc media_id:3 next_id:4 call_cnt:0 name:PCMU
Sep 30 19:58:43 192.168.42.133 core[988]: callbridge: alt_codec_test_alloc media_id:3 next_id:4 call_cnt:0 name:PCMA
Sep 30 19:58:43 192.168.42.133 core[988]: callbridge: alt_codec_test_alloc media_id:3 next_id:4 call_cnt:0 name:G722
Sep 30 19:58:43 192.168.42.133 core[988]: callbridge: alt_codec_test_alloc media_id:3 next_id:4 call_cnt:0 name:G726-32
Sep 30 19:58:43 192.168.42.133 core[988]: callbridge: alt_codec_test_alloc media_id:3 next_id:4 call_cnt:0 name:L16
Sep 30 19:58:43 192.168.42.133 core[988]: callbridge: alt_codec_test_alloc media_id:3 next_id:4 call_cnt:0 name:L16
Sep 30 19:58:43 192.168.42.133 core[988]: callbridge: alt_codec_test_alloc media_id:3 next_id:4 call_cnt:0 name:L16-256
Sep 30 19:58:43 192.168.42.133 core[988]: callbridge: 12:58:43.542 transport_srtp .generate_crypto_attr_value ingressfullKey: EF9C7DB2
Sep 30 19:58:43 192.168.42.133 core[988]: callbridge: 12:58:43.546 srtp0x29dc08 .SRTP uses keying method SDES
Sep 30 19:58:43 192.168.42.133 core[988]: callbridge: 12:58:43.547 sip_resolve.c ....DNS AAAA record resolution failed: No answer record in the DNS response (PJLIB_UTIL_EDNSNOANSWERREC)
Sep 30 19:58:43 192.168.42.133 core[988]: callbridge: 12:58:43.548 pjsua_core.c ....TX 1326 bytes Request msg INVITE/cseq=31097 (tdta0x37c69c) to TLS --redacted-server-ip--:5061:
Sep 30 19:58:43 192.168.42.133 core[988]: callbridge: 12:58:43.548 on_call_state .......Call 3 state=CALLING
Sep 30 19:58:43 192.168.42.133 core[988]: callbridge: buildCallStatus
Sep 30 19:58:43 192.168.42.133 core[988]: callbridge: state_get_call_disconnecting callid=3
Sep 30 19:58:43 192.168.42.133 core[988]: callbridge: 12:58:43.549 src/state.c .......flushing call state data for call_id 3
Sep 30 19:58:43 192.168.42.133 core[988]: callbridge: state_get_call_disconnecting callid=3
Sep 30 19:58:43 192.168.42.133 core[988]: callbridge: state_get_call_broadcom_session_info callid=3
Sep 30 19:58:43 192.168.42.133 core[988]: callbridge: 12:58:43.550 src/broadcom_p .......pjsua_call_get_stream_info: call_id:3 call_cnt:1, state:1
Sep 30 19:58:43 192.168.42.133 core[988]: callbridge: state_set_call_ingress_key callid=3
Sep 30 19:58:43 192.168.42.133 core[988]: callbridge: state_get_account_slot
Sep 30 19:58:43 192.168.42.133 core[988]: callbridge: state_get_call_handle callid=3
Sep 30 19:58:43 192.168.42.133 core[988]: callbridge: dus_send_call_status
Sep 30 19:58:43 192.168.42.133 core[988]: callbridge: state_set_call_handle callid=3
Sep 30 19:58:43 192.168.42.133 core[988]: callbridge: state_set_ringer_slot callid=3
Sep 30 19:58:43 192.168.42.133 core[988]: callbridge: 12:58:43.807 ssl_sock_ossl. !set_cipher_list calling SSL_set_cipher_list using: ALL:!aNULL:!eNULL
Sep 30 19:58:43 192.168.42.133 phone: *** State phone.idle, process event: idle_hidden
Sep 30 19:58:43 192.168.42.133 phone: VIEW EVENT: idle_hidden
Sep 30 19:58:43 192.168.42.133 phone: HomeScreen::process_event: idle_hidden
Sep 30 19:58:43 192.168.42.133 phone: REMAP EVENT idle_hidden
Sep 30 19:58:43 192.168.42.133 phone: ==== State phone.idle, process event idle_hidden: no matching transition
Sep 30 19:58:43 192.168.42.133 phone: @@@ new state: phone.idle
Sep 30 19:58:43 192.168.42.133 phone: *** State phone.idle, process event: idle_hidden
Sep 30 19:58:43 192.168.42.133 phone: VIEW EVENT: idle_hidden
Sep 30 19:58:43 192.168.42.133 phone: HomeScreen::process_event: idle_hidden
Sep 30 19:58:43 192.168.42.133 phone: REMAP EVENT idle_hidden
Sep 30 19:58:43 192.168.42.133 phone: ==== State phone.idle, process event idle_hidden: no matching transition
Sep 30 19:58:43 192.168.42.133 phone: @@@ new state: phone.idle
Sep 30 19:58:43 192.168.42.133 phone: *** State phone.idle, process event: audio_mute_status.off
Sep 30 19:58:43 192.168.42.133 phone: VIEW EVENT: audio_mute_status.off
Sep 30 19:58:43 192.168.42.133 phone: HomeScreen::process_event: audio_mute_status.off
Sep 30 19:58:43 192.168.42.133 phone: REMAP EVENT audio_mute_status.off
Sep 30 19:58:43 192.168.42.133 phone: _mute_cb value:0
Sep 30 19:58:43 192.168.42.133 phone: @@@ new state: phone.idle
Sep 30 19:58:43 192.168.42.133 phone: *** State phone.idle, process event: audio_volume_status.speakerphone.output.50
Sep 30 19:58:43 192.168.42.133 phone: VIEW EVENT: audio_volume_status.speakerphone.output.50
Sep 30 19:58:43 192.168.42.133 phone: HomeScreen::process_event: audio_volume_status.speakerphone.output.50
Sep 30 19:58:43 192.168.42.133 phone: REMAP EVENT audio_volume_status.speakerphone.output.50
Sep 30 19:58:43 192.168.42.133 phone: @@@ new state: phone.idle
Sep 30 19:58:43 192.168.42.133 phone: *** State phone.idle, process event: audio_wire_status.speakerphone
Sep 30 19:58:43 192.168.42.133 phone: VIEW EVENT: audio_wire_status.speakerphone
Sep 30 19:58:43 192.168.42.133 phone: HomeScreen::process_event: audio_wire_status.speakerphone
Sep 30 19:58:43 192.168.42.133 phone: REMAP EVENT audio_wire_status.speakerphone
Sep 30 19:58:43 192.168.42.133 phone: ACTIVE 0 CHANNEL 1 AUDIO 1
Sep 30 19:58:43 192.168.42.133 phone: @@@ new state: phone.idle
Sep 30 19:58:43 192.168.42.133 phone: *** State phone.idle, process event: idle_hidden
Sep 30 19:58:43 192.168.42.133 phone: VIEW EVENT: idle_hidden
Sep 30 19:58:43 192.168.42.133 phone: HomeScreen::process_event: idle_hidden
Sep 30 19:58:43 192.168.42.133 phone: REMAP EVENT idle_hidden
Sep 30 19:58:43 192.168.42.133 phone: ==== State phone.idle, process event idle_hidden: no matching transition
Sep 30 19:58:43 192.168.42.133 phone: @@@ new state: phone.idle
Sep 30 19:58:43 192.168.42.133 phone: *** State phone.idle, process event: call_status.CALLING.0.idle_dial_3.<sip:--redacted-phone-number--@voice\.ctrl-alt-it\.com:5061;transport=tls>..0..none.role.caller.local_info."4701-Aaron C\. de Bruyn" <sip:4701@voice\.ctrl-alt-it\.com:5061;
Sep 30 19:58:43 192.168.42.133 phone: VIEW EVENT: call_status.CALLING.0.idle_dial_3.<sip:--redacted-phone-number--@voice\.ctrl-alt-it\.com:5061;transport=tls>..0..none.role.caller.local_info."4701-Aaron C\. de Bruyn" <sip:4701@voice\.ctrl-alt-it\.com:5061;transport=tls>.local_cont
Sep 30 19:58:43 192.168.42.133 phone: HomeScreen::process_event: call_status.CALLING.0.idle_dial_3.<sip:--redacted-phone-number--@voice\.ctrl-alt-it\.com:5061;transport=tls>..0..none.role.caller.local_info."4701-Aaron C\. de Bruyn" <sip:4701@voice\.ctrl-alt-it\.com:5061;transport=
Sep 30 19:58:43 192.168.42.133 phone: REMAP EVENT call_status.CALLING.0.idle_dial_3.<sip:--redacted-phone-number--@voice\.ctrl-alt-it\.com:5061;transport=tls>..0..none.role.caller.local_info."4701-Aaron C\. de Bruyn" <sip:4701@voice\.ctrl-alt-it\.com:5061;transport=tls>.local_cont
Sep 30 19:58:43 192.168.42.133 phone: PhoneModel: call_status.CALLING.0.idle_dial_3.<sip:--redacted-phone-number--@voice\.ctrl-alt-it\.com:5061;transport=tls>..0..none.role.caller.local_info."4701-Aaron C\. de Bruyn" <sip:4701@voice\.ctrl-alt-it\.com:5061;transport=tls>.local_cont
Sep 30 19:58:43 192.168.42.133 phone: PhoneModel: NAME NUMBER --redacted-phone-number--
Sep 30 19:58:43 192.168.42.133 phone: Highest priority, 0 account
Sep 30 19:58:43 192.168.42.133 phone: dbus_audio_wire(speakerphone)
Sep 30 19:58:43 192.168.42.133 phone: ACTIVE 0 CHANNEL 1 AUDIO 1
Sep 30 19:58:43 192.168.42.133 phone: dbus_audio_set_volume(speakerphone, output, 50)
Sep 30 19:58:43 192.168.42.133 phone: ACTIVE 1 CHANNEL 1 AUDIO 1
Sep 30 19:58:43 192.168.42.133 phone: AudioStreamManager::pauseStreaming
Sep 30 19:58:43 192.168.42.133 phone: dbus_stop_tone(0)
Sep 30 19:58:43 192.168.42.133 phone: dbus_stop_tone(1)
Sep 30 19:58:43 192.168.42.133 phone: dbus_stop_file()
Sep 30 19:58:43 192.168.42.133 phone: dbus_ehs_ring(0)
Sep 30 19:58:43 192.168.42.133 phone: @@@ new state: phone.calling
Sep 30 19:58:43 192.168.42.133 phone: Indicator cb
Sep 30 19:58:43 192.168.42.133 phone: Line 0 update
Sep 30 19:58:43 192.168.42.133 phone: ACTIVITY 8
Sep 30 19:58:43 192.168.42.133 phone: _call_screen, cl_size:1, updated_call idle_dial_3 status:9
Sep 30 19:58:43 192.168.42.133 phone: _call_screen, updated_call idle_dial_3 status:9 number:--redacted-phone-number--
Sep 30 19:58:43 192.168.42.133 core[988]: core dbus_callback()
Sep 30 19:58:43 192.168.42.133 phone: dbus_request_file url http://voice.--redacted--:82/image.php?token=445d5bd5112f79254c8fd94a61458854&did=--redacted-phone-number--
Sep 30 19:58:43 192.168.42.133 phone: check_call_photo cURL url:http://voice.--redacted--:82/image.php?token=445d5bd5112f79254c8fd94a61458854&did=--redacted-phone-number-- file:/tmp/--redacted-phone-number--.png
Sep 30 19:58:43 192.168.42.133 phone: dbus_hide_idle_apps()
Sep 30 19:58:43 192.168.42.133 core[988]: callbridge: aud_set_call_device speakerphone speakerphone
Sep 30 19:58:43 192.168.42.133 core[988]: callbridge: Already on this device
Sep 30 19:58:43 192.168.42.133 core[988]: callbridge: dus_send_audio_wire_status
Sep 30 19:58:43 192.168.42.133 core[988]: callbridge: dus_send_audio_volume_status
Sep 30 19:58:43 192.168.42.133 phone: _set_top_label()
Sep 30 19:58:43 192.168.42.133 phone: _softkeys()
I have verified the certificate being used on the application port is valid using openssl.
EPM is sending the correct cert to the phone when it downloads it’s config file.
One thing I did notice was a few examples in the forums of running “openssl s_client -connect server:5061” to check the cert. With the versions of openssl available on my various boxes, I get a protocol error and “no peer certificate available”. I’m not sure if openssl is capable of checking SIP-TLS certs or not due to also not knowing if SIP-TLS requires STARTTLS first (thereby requiring openssl to be able to speak -starttls sip, which it doesn’t).
Checking pjsip show transport 0.0.0.0-tls lists valid paths for all the certs, and I compared the cert against what’s being published in /tftpboot/whatever.cfg
I haven’t gone so far as to hack /tftpboot/whatever.cfg to see if I can include the entire chain yet, but I’m thinking Digium needs to update their cert store. Of course I have completely restarted asterisk.
Anyways, I’m continuing to troubleshoot and will let everyone know if I can track down the problem.