[Workaround] thread 'Registrar' panicked at 'called `Result::unwrap()` on an `Err` value: Error { repr: Os { code: 2, message: "No such file or directory" } }'

[Yoric]

I have encountered this twice. Unfortunately, I didn't have RUSTC_BACKTRACE=1.

This has happened once during startup and once during runtime. The latter occurrence matched with me changing Wifi network, I don't know if there is causality.

Cc @ferjm , @samgiles

[Yoric]

Ah, well, since my latest rebase, it seems 100% reproducible on startup:

$ cargo run
[2016-04-13 17:05:20.148] INFO  nUPNP server: Starting registration with http://knilxof.org:4242/register
[2016-04-13 17:05:20.149] INFO  Got ip address: 10.243.30.225
thread 'Registrar' panicked at 'called `Result::unwrap()` on an `Err` value: Error { repr: Os { code: 2, message: "No such file or directory" } }', ../src/libcore/result.rs:746
stack backtrace:
   1:        0x10b8ec388 - std::sys::backtrace::tracing::imp::write::h714760a4c8c0cdd8
   2:        0x10b8f14c5 - std::panicking::default_hook::_$u7b$$u7b$closure$u7d$$u7d$::hff309ab1d83ffd90
   3:        0x10b8f10fe - std::panicking::default_hook::h08ad3bb09872855b
   4:        0x10b8da946 - std::sys_common::unwind::begin_unwind_inner::h406d5f1a330b854b
   5:        0x10b8db7de - std::sys_common::unwind::begin_unwind_fmt::h57ea3fbee1a40196
   6:        0x10b8eb657 - rust_begin_unwind
   7:        0x10b918390 - core::panicking::panic_fmt::ha6b3c19493c123b3
   8:        0x10abf3cab - core::result::unwrap_failed::he41fdbb4a3e1914b
   9:        0x10b086800 - _<core..result..Result<T, E>>::unwrap::h73493af4a956f6b0
  10:        0x10b08661f - foxbox::registration::Registrar::get_fingerprint::h07f9b00e3e21d9f6
  11:        0x10b086961 - foxbox::registration::Registrar::get_common_name::hc66bdf16d17299a5
  12:        0x10b086b2e - foxbox::registration::Registrar::get_local_dns_name::h8311cdd8bc200fb0
  13:        0x10abf7aea - foxbox::registration::Registrar::register_certificates::h0e8c10fa21ede494
  14:        0x10abf755c - foxbox::registration::Registrar::start::_$u7b$$u7b$closure$u7d$$u7d$::hc41f7cc0968818b9
  15:        0x10abf6e83 - std::thread::Builder::spawn::_$u7b$$u7b$closure$u7d$$u7d$::_$u7b$$u7b$closure$u7d$$u7d$::hd1c914397684f3e3
  16:        0x10abf6df8 - std::sys_common::unwind::try::try_fn::h3371f31bd1567284
  17:        0x10b8eb5eb - __rust_try
  18:        0x10b8eb573 - std::sys_common::unwind::inner_try::h4e97625a08807651
  19:        0x10abf6d35 - std::sys_common::unwind::try::h9fcfb8a0190106ff
  20:        0x10abf6b61 - std::thread::Builder::spawn::_$u7b$$u7b$closure$u7d$$u7d$::h9823d3398d00b5a5
  21:        0x10abf78d7 - _<F as std..boxed..FnBox<A>>::call_box::h1703109ae850d320
  22:        0x10b8f0718 - std::sys::thread::Thread::new::thread_start::h74af400293164137
  23:     0x7fff8f56fc12 - _pthread_body
  24:     0x7fff8f56fb8f - _pthread_start
[2016-04-13 17:05:20.368] INFO  UPnP search for devices matching "urn:cellvision:service:Null:1" (0)
[2016-04-13 17:05:20.368] INFO  UPnP search for devices matching "ssdp:all" (0)
[2016-04-13 17:05:20.370] INFO  Thinkerbell: Starting compilation of script 'When nobody is home, close the lock, turn off everything.'
[2016-04-13 17:05:20.370] INFO  Thinkerbell: Starting execution of script 'When nobody is home, close the lock, turn off everything.'
[2016-04-13 17:05:20.371] INFO  Thinkerbell: Starting compilation of script 'Hello, Thinkerbell 0.878509531027901'
[2016-04-13 17:05:20.371] INFO  Thinkerbell: Starting execution of script 'Hello, Thinkerbell 0.878509531027901'
[2016-04-13 17:05:20.371] INFO  Started Thinkerbell main thread.
[2016-04-13 17:05:20.372] INFO  Added Thinkerbell Rule for 'When nobody is home, close the lock, turn off everything.'
[2016-04-13 17:05:20.372] INFO  Added Thinkerbell Rule for 'Hello, Thinkerbell 0'
[2016-04-13 17:05:20.372] INFO  Started Openzwave adapter.
[2016-04-13 17:05:20.372] INFO  No tts support on this platform.
[2016-04-13 17:05:20.381] INFO  Listening for new connections on [::]:4000.
[2016-04-13 17:05:20.582] INFO  UPnP search for devices matching "ssdp:all" (0)
[2016-04-13 17:05:20.601] INFO  Starting Hue Hub Service for 001788fffe243568
[2016-04-13 17:05:20.653] INFO  Connected to Philips Hue bridge model BSB002, ID 001788FFFE243568, software version 01031131, IP address 10.243.30.142
[2016-04-13 17:05:20.675] INFO  New Philips Hue Extended Color Light service for light 1 on bridge 001788fffe243568
[2016-04-13 17:05:20.688] INFO  New Philips Hue Extended Color Light service for light 2 on bridge 001788fffe243568
[2016-04-13 17:05:20.698] INFO  New Philips Hue Extended Color Light service for light 3 on bridge 001788fffe243568

I built with authentication enabled, on a Mac.

[Yoric]

With more logs

$ RUST_BACKTRACE=1 RUST_LOG=debug cargo run
[...]
     Running `target/debug/foxbox`
WARNING: Your platform is not supported by real mDNS adapter, fake adapter is used!
WARNING: Your platform is not supported by real mDNS adapter, fake adapter is used!
[2016-04-13 17:07:04.795] DEBUG Verifying host name: foxbox.
WARNING: Your platform is not supported by real mDNS adapter, fake adapter is used!
[2016-04-13 17:07:04.795] DEBUG There is no need to do anything, just letting you know that I'm being dropped!
[2016-04-13 17:07:04.796] DEBUG Parsed config file: {"foxbox": {"certificate_directory": "certs/"}, "philips_hue": {"nupnp_enabled": "true", "nupnp_url": "http://www.meethue.com/api/nupnp", "token_001788fffe243568": "3dcb9202d21d46af9a37612dac2587df"}}
[2016-04-13 17:07:04.796] DEBUG Config result for foxbox::certificate_directory is Some("certs/")
[2016-04-13 17:07:04.797] INFO  nUPNP server: Starting registration with http://knilxof.org:4242/register
[2016-04-13 17:07:04.798] INFO  Got ip address: 10.243.30.225
[2016-04-13 17:07:04.798] DEBUG Starting controller
[2016-04-13 17:07:04.798] DEBUG Loading certificate for host ::
thread 'Registrar' panicked at 'called `Result::unwrap()` on an `Err` value: Error { repr: Os { code: 2, message: "No such file or directory" } }', ../src/libcore/result.rs:746
stack backtrace:
   1:        0x10316f388 - std::sys::backtrace::tracing::imp::write::h714760a4c8c0cdd8
   2:        0x1031744c5 - std::panicking::default_hook::_$u7b$$u7b$closure$u7d$$u7d$::hff309ab1d83ffd90
   3:        0x1031740fe - std::panicking::default_hook::h08ad3bb09872855b
   4:        0x10315d946 - std::sys_common::unwind::begin_unwind_inner::h406d5f1a330b854b
   5:        0x10315e7de - std::sys_common::unwind::begin_unwind_fmt::h57ea3fbee1a40196
   6:        0x10316e657 - rust_begin_unwind
   7:        0x10319b390 - core::panicking::panic_fmt::ha6b3c19493c123b3
   8:        0x102476cab - core::result::unwrap_failed::he41fdbb4a3e1914b
   9:        0x102909800 - _<core..result..Result<T, E>>::unwrap::h73493af4a956f6b0
  10:        0x10290961f - foxbox::registration::Registrar::get_fingerprint::h07f9b00e3e21d9f6
  11:        0x102909961 - foxbox::registration::Registrar::get_common_name::hc66bdf16d17299a5
  12:        0x102909b2e - foxbox::registration::Registrar::get_local_dns_name::h8311cdd8bc200fb0
  13:        0x10247aaea - foxbox::registration::Registrar::register_certificates::h0e8c10fa21ede494
  14:        0x10247a55c - foxbox::registration::Registrar::start::_$u7b$$u7b$closure$u7d$$u7d$::hc41f7cc0968818b9
  15:        0x102479e83 - std::thread::Builder::spawn::_$u7b$$u7b$closure$u7d$$u7d$::_$u7b$$u7b$closure$u7d$$u7d$::hd1c914397684f3e3
  16:        0x102479df8 - std::sys_common::unwind::try::try_fn::h3371f31bd1567284
  17:        0x10316e5eb - __rust_try
  18:        0x10316e573 - std::sys_common::unwind::inner_try::h4e97625a08807651
  19:        0x102479d35 - std::sys_common::unwind::try::h9fcfb8a0190106ff
  20:        0x102479b61 - std::thread::Builder::spawn::_$u7b$$u7b$closure$u7d$$u7d$::h9823d3398d00b5a5
  21:        0x10247a8d7 - _<F as std..boxed..FnBox<A>>::call_box::h1703109ae850d320
  22:        0x103173718 - std::sys::thread::Thread::new::thread_start::h74af400293164137
  23:     0x7fff8f56fc12 - _pthread_body
  24:     0x7fff8f56fb8f - _pthread_start
[2016-04-13 17:07:04.813] DEBUG initialized (0)
[2016-04-13 17:07:04.813] DEBUG registered client (0)
[2016-04-13 17:07:04.814] DEBUG Creating Adapter Manager
[2016-04-13 17:07:04.814] DEBUG Starting Philips Hue Adapter main thread
[2016-04-13 17:07:04.814] DEBUG checking if getters need to be watched [Id { id: Atom('getter:timeofday.clock@link.mozilla.org' type=dynamic), phantom: Phantom { phantom: PhantomData } }]
[2016-04-13 17:07:04.814] DEBUG checking if getters need to be watched [Id { id: Atom('getter:timestamp.clock@link.mozilla.org' type=dynamic), phantom: Phantom { phantom: PhantomData } }]
[2016-04-13 17:07:04.814] DEBUG HueAction::TriggerDiscovery received
[2016-04-13 17:07:04.814] DEBUG checking if getters need to be watched [Id { id: Atom('getter:resource.webpush@link.mozilla.org' type=dynamic), phantom: Phantom { phantom: PhantomData } }]
[2016-04-13 17:07:04.815] DEBUG checking if getters need to be watched [Id { id: Atom('getter:subscription.webpush@link.mozilla.org' type=dynamic), phantom: Phantom { phantom: PhantomData } }]
[2016-04-13 17:07:04.814] DEBUG Config result for philips_hue::nupnp_enabled is Some("true")
[2016-04-13 17:07:04.815] DEBUG Config result for philips_hue::nupnp_url is Some("http://www.meethue.com/api/nupnp")
[2016-04-13 17:07:04.815] DEBUG Querying NUPnP server at http://www.meethue.com/api/nupnp
[2016-04-13 17:07:04.815] DEBUG http scheme
[2016-04-13 17:07:04.884] DEBUG request line: Get "/api/nupnp" Http11
[2016-04-13 17:07:04.884] DEBUG headers=Headers { Connection: close, Host: www.meethue.com, }
[2016-04-13 17:07:04.969] DEBUG version=Http11, status=Found
[2016-04-13 17:07:04.969] DEBUG headers=Headers { Content-Length: 0, Content-Type: text/html, Connection: close, Location: https://www.meethue.com/api/nupnp, Date: Wed, 13 Apr 2016 15:07:04 GMT, Server: Google Frontend, }
[2016-04-13 17:07:04.969] DEBUG redirect code Found for http://www.meethue.com/api/nupnp
[2016-04-13 17:07:04.970] DEBUG https scheme

[samgiles]

Hey, I've seen this report from someone else in IRC. What's the output from ls -alR certs/?

[Yoric]

Ah, @ferjm just asked me to remove the directory, so I can't tell you what it was.

This seems to change the error, but not by much:

$ RUST_BACKTRACE=1 cargo run
   Compiling foxbox v0.1.0 (file:///Users/david/Documents/Code/fxbox/fxbox)
     Running `target/debug/foxbox`
WARNING: Your platform is not supported by real mDNS adapter, fake adapter is used!
WARNING: Your platform is not supported by real mDNS adapter, fake adapter is used!
WARNING: Your platform is not supported by real mDNS adapter, fake adapter is used!
[2016-04-13 17:09:23.803] INFO  nUPNP server: Starting registration with http://knilxof.org:4242/register
[2016-04-13 17:09:23.804] INFO  Got ip address: 10.243.30.225
[2016-04-13 17:09:23.805] INFO  Loaded certificates from directory: "certs/"
[2016-04-13 17:09:23.805] INFO  Generating new self-signed cert for foxbox.local
[2016-04-13 17:09:24.022] INFO  UPnP search for devices matching "ssdp:all" (0)
[2016-04-13 17:09:24.023] INFO  UPnP search for devices matching "urn:cellvision:service:Null:1" (0)
[2016-04-13 17:09:24.026] INFO  Thinkerbell: Starting compilation of script 'When nobody is home, close the lock, turn off everything.'
[2016-04-13 17:09:24.027] INFO  Thinkerbell: Starting execution of script 'When nobody is home, close the lock, turn off everything.'
[2016-04-13 17:09:24.027] INFO  Thinkerbell: Starting compilation of script 'Hello, Thinkerbell 0.878509531027901'
[2016-04-13 17:09:24.028] INFO  Thinkerbell: Starting execution of script 'Hello, Thinkerbell 0.878509531027901'
[2016-04-13 17:09:24.028] INFO  Started Thinkerbell main thread.
[2016-04-13 17:09:24.029] INFO  Added Thinkerbell Rule for 'When nobody is home, close the lock, turn off everything.'
[2016-04-13 17:09:24.029] INFO  Added Thinkerbell Rule for 'Hello, Thinkerbell 0'
[2016-04-13 17:09:24.031] INFO  Started Openzwave adapter.
[2016-04-13 17:09:24.031] INFO  No tts support on this platform.
[2016-04-13 17:09:24.046] INFO  Listening for new connections on [::]:4000.
[2016-04-13 17:09:24.083] INFO  Getting/renewing LetsEncrypt certificate for: ["local.15465cb3cdaa108d31836171fe557bdb5c1a5041.box.knilxof.org", "remote.15465cb3cdaa108d31836171fe557bdb5c1a5041.box.knilxof.org"]
#
# !! WARNING !! No main config file found, using default config!
#
[2016-04-13 17:09:24.241] INFO  UPnP search for devices matching "ssdp:all" (0)
+ Generating account key...
[2016-04-13 17:09:24.594] INFO  Starting Hue Hub Service for 001788fffe243568
[2016-04-13 17:09:24.651] INFO  Connected to Philips Hue bridge model BSB002, ID 001788FFFE243568, software version 01031131, IP address 10.243.30.142
[2016-04-13 17:09:24.671] INFO  New Philips Hue Extended Color Light service for light 1 on bridge 001788fffe243568
[2016-04-13 17:09:24.682] INFO  New Philips Hue Extended Color Light service for light 2 on bridge 001788fffe243568
[2016-04-13 17:09:24.694] INFO  New Philips Hue Extended Color Light service for light 3 on bridge 001788fffe243568
+ Registering account key with letsencrypt...
Processing local.15465cb3cdaa108d31836171fe557bdb5c1a5041.box.knilxof.org with alternative names: remote.15465cb3cdaa108d31836171fe557bdb5c1a5041.box.knilxof.org
 + Signing domains...
 + Creating new directory /private/var/folders/jd/xp7fdzmj5dsgz1ttljnvy8kw0000gn/T/07586655166f43c98caaa0362cb2610c/certs/local.15465cb3cdaa108d31836171fe557bdb5c1a5041.box.knilxof.org ...
 + Generating private key...
 + Generating signing request...
 + Requesting challenge for local.15465cb3cdaa108d31836171fe557bdb5c1a5041.box.knilxof.org...
 + Requesting challenge for remote.15465cb3cdaa108d31836171fe557bdb5c1a5041.box.knilxof.org...
Note: Unnecessary use of -X or --request, POST is already inferred.
*   Trying 52.36.71.23...
* Connected to knilxof.org (52.36.71.23) port 5300 (#0)
* ALPN, offering http/1.1
* could not load PEM client certificate, OpenSSL error error:0906D06C:PEM routines:PEM_read_bio:no start line, (no key found, wrong pass phrase, or wrong file format?)
* Closing connection 0
curl: (58) could not load PEM client certificate, OpenSSL error error:0906D06C:PEM routines:PEM_read_bio:no start line, (no key found, wrong pass phrase, or wrong file format?)
thread 'Registrar' panicked at 'called `Result::unwrap()` on an `Err` value: Error { repr: Custom(Custom { kind: Other, error: StringError("The LetsEncryt client failed - certificates could not be created") }) }', ../src/libcore/result.rs:746
stack backtrace:
   1:        0x10ba9e388 - std::sys::backtrace::tracing::imp::write::h714760a4c8c0cdd8
   2:        0x10baa34c5 - std::panicking::default_hook::_$u7b$$u7b$closure$u7d$$u7d$::hff309ab1d83ffd90
   3:        0x10baa30fe - std::panicking::default_hook::h08ad3bb09872855b
   4:        0x10ba8c946 - std::sys_common::unwind::begin_unwind_inner::h406d5f1a330b854b
   5:        0x10ba8d7de - std::sys_common::unwind::begin_unwind_fmt::h57ea3fbee1a40196
   6:        0x10ba9d657 - rust_begin_unwind
   7:        0x10baca390 - core::panicking::panic_fmt::ha6b3c19493c123b3
   8:        0x10ada5cab - core::result::unwrap_failed::he41fdbb4a3e1914b
   9:        0x10ada5ac1 - _<core..result..Result<T, E>>::unwrap::h7dc65f4101dfcb66
  10:        0x10adaa0fa - foxbox::registration::Registrar::register_certificates::h0e8c10fa21ede494
  11:        0x10ada955c - foxbox::registration::Registrar::start::_$u7b$$u7b$closure$u7d$$u7d$::hc41f7cc0968818b9
  12:        0x10ada8e83 - std::thread::Builder::spawn::_$u7b$$u7b$closure$u7d$$u7d$::_$u7b$$u7b$closure$u7d$$u7d$::hd1c914397684f3e3
  13:        0x10ada8df8 - std::sys_common::unwind::try::try_fn::h3371f31bd1567284
  14:        0x10ba9d5eb - __rust_try
  15:        0x10ba9d573 - std::sys_common::unwind::inner_try::h4e97625a08807651
  16:        0x10ada8d35 - std::sys_common::unwind::try::h9fcfb8a0190106ff
  17:        0x10ada8b61 - std::thread::Builder::spawn::_$u7b$$u7b$closure$u7d$$u7d$::h9823d3398d00b5a5
  18:        0x10ada98d7 - _<F as std..boxed..FnBox<A>>::call_box::h1703109ae850d320
  19:        0x10baa2718 - std::sys::thread::Thread::new::thread_start::h74af400293164137
  20:     0x7fff8f56fc12 - _pthread_body
  21:     0x7fff8f56fb8f - _pthread_start

After running this, I have the following certs/:

$ ls -alR certs/
total 0
drwxr-xr-x   3 david  staff  102 Apr 13 17:09 .
drwxr-xr-x  28 david  staff  952 Apr 13 17:09 ..
drwxr-xr-x   4 david  staff  136 Apr 13 17:09 foxbox.local

certs//foxbox.local:
total 16
drwxr-xr-x  4 david  staff   136 Apr 13 17:09 .
drwxr-xr-x  3 david  staff   102 Apr 13 17:09 ..
-rw-r--r--  1 david  staff   989 Apr 13 17:09 cert.pem
-rw-r--r--  1 david  staff  1704 Apr 13 17:09 privkey.pem

[Yoric]

I forgot to add the version of curl: curl 7.47.1 (x86_64-apple-darwin15.3.0) libcurl/7.47.1 OpenSSL/1.0.2g zlib/1.2.8. This is the latest version of MacPorts, not the version provided by default with MacOS X.

[Yoric]

The following workaround worked for me:

# Make sure that the system curl is used instead of the MacPorts versio
$ PATH=.:$PATH
$ ln -s /usr/bin/curl

# Now run foxbox
$ cargo run

edit Removing Demo Blocker since there is a workaround.

[Yoric]

So, @samgiles , I confirm that the error is due to the use of curl.