Re: [PATCH] service: Complete only after user connection retries

Re: [PATCH] service: Complete only after user connection retries

[John Keeping]

Hi,

On Sat, 27 Mar 2021 13:42:54 +0100
Daniel Wagner <wagi@monom.org> wrote:
> On Thu, Mar 11, 2021 at 01:04:11PM +0000, VAUTRIN Emmanuel (Canal Plus Prestataire) wrote:
> > When a user connection fails, let the report_error_cb manage
> > exclusively service update, after all retries.  
> 
> Patch applied.

This patch seems to have totally broken connection attempts where the
wrong passphrase is entered:

        connmanctl> connect wifi_b0f1ecffb46f_7073475462456b44_managed_psk
        Agent RequestInput wifi_b0f1ecffb46f_7073475462456b44_managed_psk
          Passphrase = [ Type=psk, Requirement=mandatory ]
        Passphrase? wrong-passphrase
        Agent ReportError wifi_b0f1ecffb46f_7073475462456b44_managed_psk
          invalid-key
        Agent request cancelled by ConnMan
        connmanctl> connect wifi_b0f1ecffb46f_7073475462456b44_managed_psk
        Error /net/connman/service/wifi_b0f1ecffb46f_7073475462456b44_managed_psk: In progress

This happens because service->pending is never cleared because
service_cleared() is bypassed in this hunk:

@@ -6064,6 +6065,7 @@ static int service_indicate_state(struct connman_service *service)
                                                report_error_cb,
                                                get_dbus_sender(service),
                                                NULL);
+                       goto notifier;
                }
                service_complete(service);
                break;

It looks like something is missing because reporting the error only
after all retries makes sense, but after this patch the original connect
request doesn't get a response at all and any future attempt to connect
fails.

I'm not familiar enough with the code flow to suggest a follow-up
change, but does the above explanation make sense?  Is there an easy way
to ensure that the pending state is cleared and we reply to the original
message?


Thanks,
John

Re: [PATCH] service: Complete only after user connection retries

[Daniel Wagner]

Hi John,

Sorry for the long delay.

On Tue, Jun 15, 2021 at 12:09:30PM +0100, John Keeping wrote:
> Hi,
> 
> On Sat, 27 Mar 2021 13:42:54 +0100
> Daniel Wagner <wagi@monom.org> wrote:
> > On Thu, Mar 11, 2021 at 01:04:11PM +0000, VAUTRIN Emmanuel (Canal Plus Prestataire) wrote:
> > > When a user connection fails, let the report_error_cb manage
> > > exclusively service update, after all retries.  
> > 
> > Patch applied.
> 
> This patch seems to have totally broken connection attempts where the
> wrong passphrase is entered:
> 
>         connmanctl> connect wifi_b0f1ecffb46f_7073475462456b44_managed_psk
>         Agent RequestInput wifi_b0f1ecffb46f_7073475462456b44_managed_psk
>           Passphrase = [ Type=psk, Requirement=mandatory ]
>         Passphrase? wrong-passphrase
>         Agent ReportError wifi_b0f1ecffb46f_7073475462456b44_managed_psk
>           invalid-key
>         Agent request cancelled by ConnMan
>         connmanctl> connect wifi_b0f1ecffb46f_7073475462456b44_managed_psk
>         Error /net/connman/service/wifi_b0f1ecffb46f_7073475462456b44_managed_psk: In progress
> 
> This happens because service->pending is never cleared because
> service_cleared() is bypassed in this hunk:
> 
> @@ -6064,6 +6065,7 @@ static int service_indicate_state(struct connman_service *service)
>                                                 report_error_cb,
>                                                 get_dbus_sender(service),
>                                                 NULL);
> +                       goto notifier;
>                 }
>                 service_complete(service);
>                 break;
> 
> It looks like something is missing because reporting the error only
> after all retries makes sense, but after this patch the original connect
> request doesn't get a response at all and any future attempt to connect
> fails.
> 
> I'm not familiar enough with the code flow to suggest a follow-up
> change, but does the above explanation make sense?  Is there an easy way
> to ensure that the pending state is cleared and we reply to the original
> message?

I've tried to reproduce it. With iwd, we never go this path as iwd tells
us invalid key directly from the connect attempt.

In case of wpa_supplicant we go through this path, meaning
report_error_cb gets called with either retry=1 or retry=0:

connmanctl> connect wifi_001e58ab5802_6f776c2073747265746368696e672074696d65_managed_psk
Agent RequestInput wifi_001e58ab5802_6f776c2073747265746368696e672074696d65_managed_psk
  Passphrase = [ Type=psk, Requirement=mandatory ]
Passphrase? asdf
Agent ReportError wifi_001e58ab5802_6f776c2073747265746368696e672074696d65_managed_psk
  invalid-key
connmanctl> Retry (yes/no)? yes
Agent RequestInput wifi_001e58ab5802_6f776c2073747265746368696e672074696d65_managed_psk
  Passphrase = [ Type=psk, Requirement=mandatory ]
Passphrase? asdf
Agent ReportError wifi_001e58ab5802_6f776c2073747265746368696e672074696d65_managed_psk
  invalid-key
connmanctl> Retry (yes/no)? no
Error /net/connman/service/wifi_001e58ab5802_6f776c2073747265746368696e672074696d65_managed_psk: Input/output error
connmanctl> connect wifi_001e58ab5802_6f776c2073747265746368696e672074696d65_managed_psk
Agent RequestInput wifi_001e58ab5802_6f776c2073747265746368696e672074696d65_managed_psk
  Passphrase = [ Type=psk, Requirement=mandatory ]
Passphrase? asdf
Agent ReportError wifi_001e58ab5802_6f776c2073747265746368696e672074696d65_managed_psk
  invalid-key
connmanctl> Retry (yes/no)? yes
Agent RequestInput wifi_001e58ab5802_6f776c2073747265746368696e672074696d65_managed_psk
  Passphrase = [ Type=psk, Requirement=mandatory ]
Passphrase? asdf
Agent ReportError wifi_001e58ab5802_6f776c2073747265746368696e672074696d65_managed_psk
  invalid-key
connmanctl> Retry (yes/no)? yes
Agent RequestInput wifi_001e58ab5802_6f776c2073747265746368696e672074696d65_managed_psk
  Passphrase = [ Type=psk, Requirement=mandatory ]
Passphrase? correct-password
Connected wifi_001e58ab5802_6f776c2073747265746368696e672074696d65_managed_psk


So the only way I can see why the pending message is not released is a
missing call to report_error_cb() or the final call is
report_error_cb(retry=1).

Could you try to add some debug printfs and report back?

Thanks,
Daniel

Re: [PATCH] service: Complete only after user connection retries

[John Keeping]

Hi Daniel,

On Mon, 28 Jun 2021 09:58:35 +0200
Daniel Wagner <wagi@monom.org> wrote:

> Sorry for the long delay.
> 
> On Tue, Jun 15, 2021 at 12:09:30PM +0100, John Keeping wrote:
> > Hi,
> > 
> > On Sat, 27 Mar 2021 13:42:54 +0100
> > Daniel Wagner <wagi@monom.org> wrote:  
> > > On Thu, Mar 11, 2021 at 01:04:11PM +0000, VAUTRIN Emmanuel (Canal Plus Prestataire) wrote:  
> > > > When a user connection fails, let the report_error_cb manage
> > > > exclusively service update, after all retries.    
> > > 
> > > Patch applied.  
> > 
> > This patch seems to have totally broken connection attempts where the
> > wrong passphrase is entered:
> >   
> >         connmanctl> connect wifi_b0f1ecffb46f_7073475462456b44_managed_psk  
> >         Agent RequestInput wifi_b0f1ecffb46f_7073475462456b44_managed_psk
> >           Passphrase = [ Type=psk, Requirement=mandatory ]
> >         Passphrase? wrong-passphrase
> >         Agent ReportError wifi_b0f1ecffb46f_7073475462456b44_managed_psk
> >           invalid-key
> >         Agent request cancelled by ConnMan  
> >         connmanctl> connect wifi_b0f1ecffb46f_7073475462456b44_managed_psk  
> >         Error /net/connman/service/wifi_b0f1ecffb46f_7073475462456b44_managed_psk: In progress
> > 
> > This happens because service->pending is never cleared because
> > service_cleared() is bypassed in this hunk:
> > 
> > @@ -6064,6 +6065,7 @@ static int service_indicate_state(struct connman_service *service)
> >                                                 report_error_cb,
> >                                                 get_dbus_sender(service),
> >                                                 NULL);
> > +                       goto notifier;
> >                 }
> >                 service_complete(service);
> >                 break;
> > 
> > It looks like something is missing because reporting the error only
> > after all retries makes sense, but after this patch the original connect
> > request doesn't get a response at all and any future attempt to connect
> > fails.
> > 
> > I'm not familiar enough with the code flow to suggest a follow-up
> > change, but does the above explanation make sense?  Is there an easy way
> > to ensure that the pending state is cleared and we reply to the original
> > message?  
> 
> I've tried to reproduce it. With iwd, we never go this path as iwd tells
> us invalid key directly from the connect attempt.
> 
> In case of wpa_supplicant we go through this path, meaning
> report_error_cb gets called with either retry=1 or retry=0:
> 
> connmanctl> connect wifi_001e58ab5802_6f776c2073747265746368696e672074696d65_managed_psk  
> Agent RequestInput wifi_001e58ab5802_6f776c2073747265746368696e672074696d65_managed_psk
>   Passphrase = [ Type=psk, Requirement=mandatory ]
> Passphrase? asdf
> Agent ReportError wifi_001e58ab5802_6f776c2073747265746368696e672074696d65_managed_psk
>   invalid-key
> connmanctl> Retry (yes/no)? yes  
> Agent RequestInput wifi_001e58ab5802_6f776c2073747265746368696e672074696d65_managed_psk
>   Passphrase = [ Type=psk, Requirement=mandatory ]
> Passphrase? asdf
> Agent ReportError wifi_001e58ab5802_6f776c2073747265746368696e672074696d65_managed_psk
>   invalid-key
> connmanctl> Retry (yes/no)? no  
> Error /net/connman/service/wifi_001e58ab5802_6f776c2073747265746368696e672074696d65_managed_psk: Input/output error
> connmanctl> connect wifi_001e58ab5802_6f776c2073747265746368696e672074696d65_managed_psk  
> Agent RequestInput wifi_001e58ab5802_6f776c2073747265746368696e672074696d65_managed_psk
>   Passphrase = [ Type=psk, Requirement=mandatory ]
> Passphrase? asdf
> Agent ReportError wifi_001e58ab5802_6f776c2073747265746368696e672074696d65_managed_psk
>   invalid-key
> connmanctl> Retry (yes/no)? yes  
> Agent RequestInput wifi_001e58ab5802_6f776c2073747265746368696e672074696d65_managed_psk
>   Passphrase = [ Type=psk, Requirement=mandatory ]
> Passphrase? asdf
> Agent ReportError wifi_001e58ab5802_6f776c2073747265746368696e672074696d65_managed_psk
>   invalid-key
> connmanctl> Retry (yes/no)? yes  
> Agent RequestInput wifi_001e58ab5802_6f776c2073747265746368696e672074696d65_managed_psk
>   Passphrase = [ Type=psk, Requirement=mandatory ]
> Passphrase? correct-password
> Connected wifi_001e58ab5802_6f776c2073747265746368696e672074696d65_managed_psk
> 
> 
> So the only way I can see why the pending message is not released is a
> missing call to report_error_cb() or the final call is
> report_error_cb(retry=1).
> 
> Could you try to add some debug printfs and report back?

It looks like the length of the invalid passphrase matters here.  If I
use a short passphrase like you have above then I reproduce that
behaviour, but if the wrong passphrase has at least 8 characters then it
enters the failure state.

I think __connman_service_check_passphrase() is rejecting the short
passphrase so it never even gets to wpa_supplicant.

In the failing case, I don't get the chance to choose to retry.  Instead
the output looks like:

	Passphrase? asdfgghjgj
	Agent ReportError wifi_b0f1ecffb46f_7073475462456b44_managed_psk
	  invalid-key
	Agent request cancelled by ConnMan
	Retry (yes/no)? connmanctl>

where the new prompt appears instantly.  Inspecting the DBus traffic, I
see that connman calls Agent.ReportError and then immediately calls
Agent.Cancel (the timestamp is less than a millisecond later, although
there is a call to fi.w1.fpa_supplicant1.Interface.Disconnect in
between).

I added extra logging in report_error_cb() and can confirm that this is
never called when this happens.


Regards,
John

Re: [PATCH] service: Complete only after user connection retries

[Daniel Wagner]

Hi John,

On Mon, Jun 28, 2021 at 04:04:13PM +0100, John Keeping wrote:
> > Could you try to add some debug printfs and report back?
> 
> It looks like the length of the invalid passphrase matters here.  If I
> use a short passphrase like you have above then I reproduce that
> behaviour, but if the wrong passphrase has at least 8 characters then it
> enters the failure state.

D'oh! You are so right :)

> I think __connman_service_check_passphrase() is rejecting the short
> passphrase so it never even gets to wpa_supplicant.
> 
> In the failing case, I don't get the chance to choose to retry.  Instead
> the output looks like:
> 
> 	Passphrase? asdfgghjgj
> 	Agent ReportError wifi_b0f1ecffb46f_7073475462456b44_managed_psk
> 	  invalid-key
> 	Agent request cancelled by ConnMan
> 	Retry (yes/no)? connmanctl>
> 
> where the new prompt appears instantly.  Inspecting the DBus traffic, I
> see that connman calls Agent.ReportError and then immediately calls
> Agent.Cancel (the timestamp is less than a millisecond later, although
> there is a call to fi.w1.fpa_supplicant1.Interface.Disconnect in
> between).
> 
> I added extra logging in report_error_cb() and can confirm that this is
> never called when this happens.

Alright, we are getting closer. Hmm, just an idea what could happen is
the agent state machine gets canceled (the supplicant is likely to say,
password is not working) and this it eats up the pending callback.

Thanks,
Daniel

Re: [PATCH] service: Complete only after user connection retries

[Daniel Wagner]

Hi John,

On Mon, Jun 28, 2021 at 09:54:11PM +0200, Daniel Wagner wrote:
> Alright, we are getting closer. Hmm, just an idea what could happen is
> the agent state machine gets canceled (the supplicant is likely to say,
> password is not working) and this it eats up the pending callback.

I think I found the place were lost the callback. I just send out the
patch. Please give it a go. If possible please also test some other use
cases. I am not sure if this change is not introduce another
regression...

Thanks,
Daniel