#1556 Autostart issue with encrypted private key

Reporter Anon Ymus
Owner Nobody
Created
Updated
Stars ★ (1)
Tags
  • Type-Defect
  • Priority-Medium
  • Status-Accepted
  1. Anon Ymus on

    What steps will reproduce the problem? 1. Put password protected private key and the corresponding certificate in place (certs folder) 2. Create vhost and add ssl definition to it including the password 3. Power the server off and on again What is the expected output? Prosody should find and load the ssl certificate What do you see instead? "No certificate/key found for <vhost>" What version of the product are you using? On what operating system? 0.11.5 Please provide any additional information below. Starting prosody manually with "prosodyctl start" is working.

  2. Anon Ymus on

    Defining ssl in the global section helped me with this one. Issue can be closed. Thanks

  3. Zash on

    Hey. What exactly did you put in your config? Per-host `ssl` sections are supposed to work.

  4. Zash on

    Hey. What exactly did you put in your config? Per-vhost `ssl` sections are supposed to work.

    Changes
    • tags Status-NeedInfo
  5. Anon Ymus on

    Hello, I put it like this: ssl = { key = "/path/to/key.pem"; certificate = "/path/to/cert.pem"; password = "passwordforkey"; }

  6. Anon Ymus on

    Update: it seems my issue is not resolved different to what I stated earlier. Any ideas what could be wrong? I am not sure anymore about the cause of the problem (Prosody does not autostart on Debian although installed through repository like so https://prosody.im/download/package_repository).

  7. Zash on

    This is not enough information to go on. Please provide the full config file.

  8. Anon Ymus on

    The config looks like this: admins = { } modules_enabled = { "roster"; "saslauth"; "tls"; "dialback"; "disco"; "carbons"; "pep"; "private"; "vcard4"; "vcard_legacy"; "version"; "uptime"; "time"; "ping"; "register"; "admin_adhoc"; } modules_disabled = { "s2s"; } allow_registration = false ssl = { key = "/etc/prosody/certs/key.pem"; certificate = "/etc/prosody/certs/cert.pem"; password = "############"; } c2s_require_encryption = true s2s_require_encryption = true s2s_secure_auth = true pidfile = "prosody.pid" authentication = "internal_hashed" archive_expires_after = "1w" log = { debug = "/var/log/prosody/prosody.log"; error = "/var/log/prosody/prosody.err"; } certificates = "certs" VirtualHost "localhost" VirtualHost "my-server.domain.tld" enabled = true ssl = { key = "/etc/prosody/certs/key.pem"; certificate = "/etc/prosody/certs/cert.pem"; password = "############"; }

  9. Zash on

    Have you tested whether TLS works? Could you paste the full log line and some surrounding lines please.

  10. Anon Ymus on

    I am using the default, don´t know if it is TLS. On the first start of the machine there is only this in the logs: startup info Hello and welcome to Prosody version 0.11.5 stats debug Statistics disabled and that´s it. I changed the config slightly, save it shutdown and start the machine again and the log looks like this: startup info Hello and welcome to Prosody version 0.11.5 stats debug Statistics disabled certmanager debug Searching /etc/prosody/certs for a key and certificate for client_https... certmanager debug No certificate/key found for client_https startup info Prosody is using the select backend for connection handling hostmanager debug Activated host: localhost usermanager debug Host 'localhost' now set to use user provider 'internal_hashed' storagemanager debug map storage driver unavailable, using shim on top of keyval store. storagemanager debug map storage driver unavailable, using shim on top of keyval store. modulemanager debug pep is already loaded for localhost, so not loading again localhost:tls debug Creating context for c2s certmanager debug Searching /etc/prosody/certs for a key and certificate for localhost... certmanager debug Selecting certificate /etc/prosody/certs/localhost.crt with key /etc/prosody/certs/localhost.key for localhost localhost:tls debug Creating context for s2sout certmanager debug Searching /etc/prosody/certs for a key and certificate for localhost... certmanager debug Selecting certificate /etc/prosody/certs/localhost.crt with key /etc/prosody/certs/localhost.key for localhost localhost:tls debug Creating context for s2sin certmanager debug Searching /etc/prosody/certs for a key and certificate for localhost... certmanager debug Selecting certificate /etc/prosody/certs/localhost.crt with key /etc/prosody/certs/localhost.key for localhost portmanager debug No active service for c2s, activating... socket debug server.lua: new server listener on '[*]:5222' portmanager debug Added listening service c2s to [*]:5222 socket debug server.lua: new server listener on '[::]:5222' portmanager debug Added listening service c2s to [::]:5222 portmanager info Activated service 'c2s' on [*]:5222, [::]:5222 portmanager debug No active service for legacy_ssl, activating... portmanager info Activated service 'legacy_ssl' on no ports hostmanager debug Activated host: my-server.domain.tld usermanager debug Host 'my-server.domain.tld' now set to use user provider 'internal_hashed' storagemanager debug map storage driver unavailable, using shim on top of keyval store. storagemanager debug map storage driver unavailable, using shim on top of keyval store. modulemanager debug pep is already loaded for my-server.domain.tld, so not loading again my-server.domain.tld:tls debug Creating context for c2s certmanager debug Searching /etc/prosody/certs for a key and certificate for my-server.domain.tld... certmanager debug No certificate/key found for my-server.domain.tld certmanager debug Searching /etc/prosody/certs for a key and certificate for domain.tld... certmanager debug No certificate/key found for domain.tld certmanager debug Searching /etc/prosody/certs for a key and certificate for de... certmanager debug No certificate/key found for de my-server.domain.tld:tls debug Creating context for s2sout certmanager debug Searching /etc/prosody/certs for a key and certificate for my.domain.tld... certmanager debug No certificate/key found for my-server.domain.tld certmanager debug Searching /etc/prosody/certs for a key and certificate for domain.tld... certmanager debug No certificate/key found for domain.tld certmanager debug Searching /etc/prosody/certs for a key and certificate for de... certmanager debug No certificate/key found for de my-server.domain.tld:tls debug Creating context for s2sin certmanager debug Searching /etc/prosody/certs for a key and certificate for my-server.domain.tld... certmanager debug No certificate/key found for my-server.domain.tld certmanager debug Searching /etc/prosody/certs for a key and certificate for domain.tld... certmanager debug No certificate/key found for domain.tld certmanager debug Searching /etc/prosody/certs for a key and certificate for de... certmanager debug No certificate/key found for de socket debug server.lua: accepted new client connection from ###.###.###.###:#### to 5222 a1b2c3d4e5f6g7 info Client connected a1b2c3d4e5f6g7 debug Client sent opening <stream:stream> to my-server.domain.tld a1b2c3d4e5f6g7 debug Sending[c2s_unauthed]: <?xml version='1.0'?> a1b2c3d4e5f6g7 debug Sending[c2s_unauthed]: <stream:stream version='1.0' from='my-server.domain.tld' id='#######' xmlns:stream='http://etherx.jabber.org/streams' xmlns='jabber:client' xml:lang='en'> a1b2c3d4e5f6g7 debug Sent reply <stream:stream> to client a1b2c3d4e5f6g7 debug Not offering authentication on insecure connection a1b2c3d4e5f6g7 debug Sending[c2s_unauthed]: <stream:features> runner####### debug creating new coroutine a1b2c3d4e5f6g7 debug Received[c2s_unauthed]: <starttls xmlns='urn:ietf:params:xml:ns:xmpp-tls'> a1b2c3d4e5f6g7 debug Sending[c2s_unauthed]: <proceed xmlns='urn:ietf:params:xml:ns:xmpp-tls'> socket debug server.lua: we need to do tls, but delaying until send buffer empty a1b2c3d4e5f6g7 debug TLS negotiation started for c2s_unauthed... socket debug server.lua: attempting to start tls on tcp{client}: ####### socket debug server.lua: ssl handshake done a1b2c3d4e5f6g7 debug Client sent opening <stream:stream> to my-server.domain.tld a1b2c3d4e5f6g7 debug Sending[c2s_unauthed]: <?xml version='1.0'?> a1b2c3d4e5f6g7 debug Sending[c2s_unauthed]: <stream:stream version='1.0' from='my-server.domain.tld' id='#######' xmlns:stream='http://etherx.jabber.org/streams' xmlns='jabber:client' xml:lang='en'> a1b2c3d4e5f6g7 debug Sent reply <stream:stream> to client a1b2c3d4e5f6g7 info Stream encrypted (TLSv1.2 with ECDHE-RSA-AES256-GCM-SHA384) a1b2c3d4e5f6g7 debug Offering mechanism PLAIN a1b2c3d4e5f6g7 debug Offering mechanism SCRAM-SHA-1-PLUS a1b2c3d4e5f6g7 debug Offering mechanism SCRAM-SHA-1 a1b2c3d4e5f6g7 debug Sending[c2s_unauthed]: <stream:features> a1b2c3d4e5f6g7 debug Received[c2s_unauthed]: <auth xmlns='urn:ietf:params:xml:ns:xmpp-sasl' mechanism='SCRAM-SHA-1'> my-server.domain.tld:saslauth debug sasl reply: <challenge xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>#######=</challenge> a1b2c3d4e5f6g7 debug Sending[c2s_unauthed]: <challenge xmlns='urn:ietf:params:xml:ns:xmpp-sasl'> a1b2c3d4e5f6g7 debug Received[c2s_unauthed]: <response xmlns='urn:ietf:params:xml:ns:xmpp-sasl'> a1b2c3d4e5f6g7 info Authenticated as client@my-server.domain.tld my-server.domain.tld:saslauth debug sasl reply: <success xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>#######</success> a1b2c3d4e5f6g7 debug Sending[c2s_unbound]: <success xmlns='urn:ietf:params:xml:ns:xmpp-sasl'> a1b2c3d4e5f6g7 debug Client sent opening <stream:stream> to my-server.domain.tld a1b2c3d4e5f6g7 debug Sending[c2s_unbound]: <?xml version='1.0'?> a1b2c3d4e5f6g7 debug Sending[c2s_unbound]: <stream:stream version='1.0' from='my-server.domain.tld' id='#######' xmlns:stream='http://etherx.jabber.org/streams' xmlns='jabber:client' xml:lang='en'> a1b2c3d4e5f6g7 debug Sent reply <stream:stream> to client a1b2c3d4e5f6g7 debug Sending[c2s_unbound]: <stream:features> a1b2c3d4e5f6g7 debug Received[c2s_unbound]: <iq type='set' id='#######'> rostermanager debug load_roster: asked for: client@my-server.domain.tld rostermanager debug load_roster: loading for new user: client@my-server.domain.tld a1b2c3d4e5f6g7 debug No legacy vCard to migrate or already migrated a1b2c3d4e5f6g7 debug Sending[c2s]: <iq type='result' id='#######'> a1b2c3d4e5f6g7 debug Resource bound: client@my-server.domain.tld/clientapp a1b2c3d4e5f6g7 debug Received[c2s]: <iq type='get' id='#######'> a1b2c3d4e5f6g7 debug Sending[c2s]: <iq type='result' to='client@my-server.domain.tld/clientapp' id='#######'> a1b2c3d4e5f6g7 debug Received[c2s]: <iq type='get' id='#######'> my-server.domain.tld:pep debug get_pep_service("client") my-server.domain.tld:pep debug Creating new persistent item store for user client, node "#######" my-server.domain.tld:pep debug Creation of itemstore for node ####### with config table: ####### my-server.domain.tld:pep debug Creating new persistent item store for user client, node "#######" my-server.domain.tld:pep debug Creation of itemstore for node ####### with config table: ####### my-server.domain.tld:pep debug Restoring nodes for user client my-server.domain.tld:pep debug Restoring node "#######" my-server.domain.tld:pep debug Restoring node "#######" a1b2c3d4e5f6g7 debug Sending[c2s]: <iq type='result' to='client@my-server.domain.tld/clientapp' id='#######'> a1b2c3d4e5f6g7 debug Received[c2s]: <presence id='#######'> my-server.domain.tld:pep debug get_pep_service("client") a1b2c3d4e5f6g7 debug Sending[c2s]: <iq type='get' to='client@my-server.domain.tld/clientapp' from='client@my-server.domain.tld' id='disco'> a1b2c3d4e5f6g7 debug Sending[c2s]: <presence from='client@my-server.domain.tld/clientapp' id='#######'> my-server.domain.tld:pep debug get_pep_service("client") a1b2c3d4e5f6g7 debug Sending[c2s]: <iq type='get' to='client@my-server.domain.tld/clientapp' from='client1@my-server.domain.tld' id='disco'> my-server.domain.tld:presence debug outbound presence probe from client@my-server.domain.tld for client1@my-server.domain.tld my-server.domain.tld:presence debug inbound presence probe from client@my-server.domain.tld for client1@my-server.domain.tld my-server.domain.tld:presence debug broadcasted presence of 0 resources from client1@my-server.domain.tld to client@my-server.domain.tld/clientapp a1b2c3d4e5f6g7 debug Sending[c2s]: <presence type='unavailable' from='client1@my-server.domain.tld' to='client@my-server.domain.tld/clientapp'> datamanager debug Removing empty offline datastore for user client@my-server.domain.tld a1b2c3d4e5f6g7 debug Received[c2s]: <presence id='#######'> my-server.domain.tld:pep debug get_pep_service("client") a1b2c3d4e5f6g7 debug Sending[c2s]: <iq type='get' to='client@my-server.domain.tld/clientapp' from='client@my-server.domain.tld' id='disco'> a1b2c3d4e5f6g7 debug Sending[c2s]: <presence from='client@my-server.domain.tld/clientapp' id='#######'> my-server.domain.tld:pep debug get_pep_service("client") a1b2c3d4e5f6g7 debug Sending[c2s]: <iq type='get' to='client@my-server.domain.tld/clientapp' from='client1@my-server.domain.tld' id='disco'> a1b2c3d4e5f6g7 debug Received[c2s]: <iq type='result' to='client@my-server.domain.tld' id='disco'> stanzarouter debug Discarding iq from c2s of type: result a1b2c3d4e5f6g7 debug Received[c2s]: <iq type='get' to='client@my-server.domain.tld' id='#######'> my-server.domain.tld:pep debug get_pep_service("client") a1b2c3d4e5f6g7 debug Sending[c2s]: <iq type='result' to='client@my-server.domain.tld/clientapp' id='#######'> a1b2c3d4e5f6g7 debug Received[c2s]: <presence id='#######'> my-server.domain.tld:pep debug get_pep_service("client") a1b2c3d4e5f6g7 debug Sending[c2s]: <iq type='get' to='client@my-server.domain.tld/clientapp' from='client@my-server.domain.tld' id='disco'> a1b2c3d4e5f6g7 debug Sending[c2s]: <presence from='client@my-server.domain.tld/clientapp' id='#######'> my-server.domain.tld:pep debug get_pep_service("client") a1b2c3d4e5f6g7 debug Sending[c2s]: <iq type='get' to='client@my-server.domain.tld/clientapp' from='client1@my-server.domain.tld' id='disco'> a1b2c3d4e5f6g7 debug Received[c2s]: <iq type='result' to='client1@my-server.domain.tld' id='disco'> stanzarouter debug Discarding iq from c2s of type: result a1b2c3d4e5f6g7 debug Received[c2s]: <presence id='#######'> my-server.domain.tld:pep debug get_pep_service("client") a1b2c3d4e5f6g7 debug Sending[c2s]: <iq type='get' to='client@my-server.domain.tld/clientapp' from='client@my-server.domain.tld' id='disco'> a1b2c3d4e5f6g7 debug Sending[c2s]: <presence from='client@my-server.domain.tld/clientapp' id='#######'> my-server.domain.tld:pep debug get_pep_service("client") a1b2c3d4e5f6g7 debug Sending[c2s]: <iq type='get' to='client@my-server.domain.tld/clientapp' from='client1@my-server.domain.tld' id='disco'> a1b2c3d4e5f6g7 debug Received[c2s]: <iq type='result' to='client@my-server.domain.tld' id='disco'> stanzarouter debug Discarding iq from c2s of type: result a1b2c3d4e5f6g7 debug Received[c2s]: <iq type='result' to='client1@my-server.domain.tld' id='disco'> stanzarouter debug Discarding iq from c2s of type: result a1b2c3d4e5f6g7 debug Received[c2s]: <iq type='set' id='#######'> my-server.domain.tld:carbons debug client@my-server.domain.tld/clientapp enabled carbons a1b2c3d4e5f6g7 debug Sending[c2s]: <iq type='result' to='client@my-server.domain.tld/clientapp' id='#######'> a1b2c3d4e5f6g7 debug Received[c2s]: <iq type='get' to='my-server.domain.tld' id='#######'> a1b2c3d4e5f6g7 debug Sending[c2s]: <iq type='result' from='my-server.domain.tld' to='client@my-server.domain.tld/clientapp' id='#######'> a1b2c3d4e5f6g7 debug Received[c2s]: <iq type='result' to='client@my-server.domain.tld' id='disco'> stanzarouter debug Discarding iq from c2s of type: result a1b2c3d4e5f6g7 debug Received[c2s]: <iq type='result' to='client1@my-server.domain.tld' id='disco'> stanzarouter debug Discarding iq from c2s of type: result a1b2c3d4e5f6g7 debug Received[c2s]: <iq type='result' to='client@my-server.domain.tld' id='disco'> stanzarouter debug Discarding iq from c2s of type: result a1b2c3d4e5f6g7 debug Received[c2s]: <iq type='result' to='client1@my-server.domain.tld' id='disco'> stanzarouter debug Discarding iq from c2s of type: result a1b2c3d4e5f6g7 debug Received[c2s]: <iq type='get' to='my-server.domain.tld' id='#######'> stanzarouter debug Unhandled c2s stanza: iq; xmlns=http://jabber.org/protocol/jinglenodes a1b2c3d4e5f6g7 debug Sending[c2s]: <iq type='error' from='my-server.domain.tld' to='client@my-server.domain.tld/clientapp' id='#######'>

  11. Zash on

    What you reported are debug messages, not errors. The solution is to disable debug logging and stop worrying. Your log shows TLS enabled successfully, so the configured certificate must be working. Those are completely harmless, Prosody is looking for certs as per automatic zero-config certificate location. This happens before adding settings from the config. Ignore it.

    Changes
    • tags Status-Invalid
  12. Anon Ymus on

    I am not sure if you understood the issue. When the machine starts the very first time prosody does not start automatically although enabled within systemd on Debian. I have to login and start it manually. The log I posted is after I shut down the machine after the very first boot and started it again. So the question is why isn´t prosody start at the very first time.

  13. Zash on

    Ok, sorry. I was confused by mention of certificate things. After it just stops, what does systemd report as its status? Are there any traces in syslog or the journal?

    Changes
    • tags Status-Invalid Status-NeedInfo
  14. Anon Ymus on

    Here is an syslog-excerpt of the very first start: systemd: Started Login Service. systemd: Starting Raise network interfaces... systemd: Started Raise network interfaces. systemd: Reached target Network. systemd: Starting Permit User Sessions... systemd: Starting OpenBSD Secure Shell server... systemd: Reached target Network is Online. systemd: Started Prosody XMPP Server. systemd: Starting Daily apt download activities... systemd: Started Permit User Sessions. systemd: Started Getty on tty1. systemd: Reached target Login Prompts. systemd: Reloading Prosody XMPP Server. systemd: Reloaded Prosody XMPP Server. systemd: prosody.service: Main process exited, code=killed, status=1/HUP systemd: prosody.service: Succeeded. rsyslogd: rsyslogd was HUPed rsyslogd: rsyslogd was HUPed systemd: logrotate.service: Succeeded. After shutting down and starting again the reloading part is not shown again. Only "Started Prosody XMPP Server".

  15. Zash on

    That's weird. So, it's being sent the reload signal before it has set up signal handling, which results in the default signal action of being killed.

    Changes
    • tags Status-Accepted
  16. Anon Ymus on

    I´m glad we narrowed it down.

  17. Anon Ymus on

    Any progress on this one? Have you been able to reproduce/find the reason for this issue?

  18. Zash on

    No progress, sorry.

  19. Anon Ymus on

    I solved this issue by changing the following parameter of the prosody service file found under /lib/systemd/system/prosody.service: Restart=on-abnormal changed to Restart=always With this change prosody will not fail to start anymore.

  20. Anon Ymus on

    I want to revert my previous comment because this issue might be caused by the definition of the pid-file in prosody.cfg.lua. I commented it out and it is working fine so far even without changing anything in the prosody.service file mentioned above.

New comment

Not published. Used for spam prevention and optional update notifications.