MMS not working - unknown group "sailfish-mms" ?

[Sagittarii]

I have setup a new Pro1 with a SIM card that was previously in a Jolla1, and made a backup import from the Jolla1 so got my settings as close as possible to what was before on the (mostly) working Jolla1.

I have not been able to send or receive any MMS yet.

I already got sometimes some trouble with the Jolla1, where the trick was to disconnect Wifi and switch to 3G to make it work, so the problem may not be in the Pro1 port.

So I tried to find more info on the error (as there is only a 15 minutes wait, that finishes with a notification (popup and present on the event page) that the message cannot be sent/received. On TJC there are some commands : https://together.jolla.com/question/38555/mms-issues-hints-for-debugging-and-helping-us-to-improve/

Trying this, I get some access errors in the trace:

[nemo@Pro1 ~]$ mms-engine -vkat
2020-08-10 21:32:50 [dbusaccess] WARNING: Unknown group "sailfish-mms"
2020-08-10 21:32:50 [dbusaccess] WARNING: Unknown group "sailfish-mms"
2020-08-10 21:32:50 [dbusaccess] WARNING: Unknown group "sailfish-mms"
2020-08-10 21:32:50 [mms-engine] Version 1.0.68 starting
2020-08-10 21:32:50 [mms-engine] Attaching to system bus
2020-08-10 21:32:50 [ofonoext] Bus connected
2020-08-10 21:32:50 [mms-engine] Bus acquired, starting...
2020-08-10 21:32:50 [ofonoext] Name 'org.ofono' is owned by :1.10
2020-08-10 21:32:50 [mms-engine] Acquired service name 'org.nemomobile.MmsEngine'
2020-08-10 21:32:50 [ofonoext] Interface version 8
2020-08-10 21:32:50 [dbusaccess] Parsing /proc/7381/status
2020-08-10 21:32:50 [mms-ofono] Modem '/ril_0'
2020-08-10 21:32:50 [mms-connman-nemo] Default SIM at /ril_0
2020-08-10 21:32:50 [mms-ofono] Name 'org.ofono' is owned by :1.10
2020-08-10 21:32:50 [mms-ofono] 2 modem(s) found
2020-08-10 21:32:50 [mms-ofono] SIM ril_0 is present
2020-08-10 21:32:59 [mms-engine] Processing push 96 bytes from XXXXXXXXXXXXXXX
2020-08-10 21:32:59 [mms-dispatcher] Retrieve[8342] READY
2020-08-10 21:32:59 [mms-task] Retrieve[8342] READY -> NEED_CONNECTION
2020-08-10 21:32:59 [mms-connection-nemo] MMS modem path /ril_0
2020-08-10 21:32:59 [mms-ofono] ril_0: not attached
2020-08-10 21:32:59 [mms-connection-nemo] MMS context /ril_0/context2
2020-08-10 21:32:59 [mms-connection-nemo] MessageProxy: 62.201.129.226:8080
2020-08-10 21:32:59 [mms-connection-nemo] MessageCenter: http://mms.bouyguestelecom.fr/mms/wapenc
2020-08-10 21:32:59 [mms-connection-nemo] Activate /ril_0/context2
2020-08-10 21:32:59 [mms-ofono] Activating /ril_0/context2
2020-08-10 21:32:59 [mms-ofono] ERROR: GDBus.Error:org.ofono.Error.AccessDenied: Operation not permitted
2020-08-10 21:32:59 [mms-ofono] Giving up on /ril_0/context2
2020-08-10 21:32:59 [mms-dispatcher] XXXXXXXXXXXXXXX FAILED
2020-08-10 21:32:59 [mms-task] Retrieve[8342] NEED_CONNECTION -> SLEEP
2020-08-10 21:32:59 [mms-connection-nemo] Connection XXXXXXXXXXXXXXX cancelled
2020-08-10 21:32:59 [mms-connection-nemo] Released /ril_0
2020-08-10 21:33:15 [mms-task] Retrieve[8342] SLEEP -> READY
2020-08-10 21:33:15 [mms-dispatcher] Retrieve[8342] READY
2020-08-10 21:33:15 [mms-task] Retrieve[8342] READY -> NEED_CONNECTION
2020-08-10 21:33:15 [mms-connection-nemo] MMS modem path /ril_0
2020-08-10 21:33:15 [mms-ofono] ril_0: not attached
2020-08-10 21:33:15 [mms-connection-nemo] MMS context /ril_0/context2
2020-08-10 21:33:15 [mms-connection-nemo] MessageProxy: 62.201.129.226:8080
2020-08-10 21:33:15 [mms-connection-nemo] MessageCenter: http://mms.bouyguestelecom.fr/mms/wapenc
2020-08-10 21:33:15 [mms-connection-nemo] Activate /ril_0/context2
2020-08-10 21:33:15 [mms-ofono] Activating /ril_0/context2
2020-08-10 21:33:15 [mms-ofono] ERROR: GDBus.Error:org.ofono.Error.AccessDenied: Operation not permitted
2020-08-10 21:33:15 [mms-ofono] Giving up on /ril_0/context2
2020-08-10 21:33:15 [mms-dispatcher] XXXXXXXXXXXXXXX FAILED
2020-08-10 21:33:15 [mms-task] Retrieve[8342] NEED_CONNECTION -> SLEEP
2020-08-10 21:33:15 [mms-connection-nemo] Connection XXXXXXXXXXXXXXX cancelled
2020-08-10 21:33:15 [mms-connection-nemo] Released /ril_0

The trace goes on and on, retrying continuously but slowing (every 15 seconds, then every minute...), the part between "Retrieve[8342] SLEEP -> READY" and "Released /ril_0`". I also replaced some number that I wasn't sure if it was personal data by XXXX.

In this trace, I find the following 2 lines surprising :
[dbusaccess] WARNING: Unknown group "sailfish-mms"
[mms-ofono] ERROR: GDBus.Error:org.ofono.Error.AccessDenied: Operation not permitted

This looks like some group is missing, so there is a dbus call that fails, so can't activate the proper context and stops until next retry.
This could be due to changes in newer sailfish that this command cannot anymore be called from nemo user.

Do you have the same results ? Others ? Any ideas of commands to test to get more details ?

[piggz]

Thanks for the detail report, def looks like the new sailfish group creation stuff so should be fixable, we;ve already done some similar fixes. I gotta ask thou, who is using MMS these days ???????

[Kabouik]

I am. It's dumb and therefore works on all phones, even feature phones. The big advantage is also it requires no installation at all, and no "add friend to group" thingie, so very convenient for sending stuff to people who do not belong to your usual groups/circles. However, I am not getting the issues here. MMS actually never worked this well on Sailfish for me, works 100% of the time instead of 10% or less on Jolla, Jolla C and X Compact with the same operator (Freemobile).

…

On 2020-08-11 19:09 Adam Pigg ***@***.***> wrote: Thanks for the detail report, def looks like the new sailfish group creation stuff so should be fixable, we;ve already done some similar fixes. I gotta ask thou, who is using MMS these days ??????? — You are receiving this because you are subscribed to this thread. Reply to this email directly, [1]view it on GitHub, or [2]unsubscribe. References 1. #4 2#issuecomment-672103871 2. https://github.com/notifications/unsubscribe-auth/ABWHHQ2LGSHVNQU 6RRSOX3LSAF3LZANCNFSM4P2JQ6OA

[piggz]

After some research, mms-engine should work for either theprivileged group or sailfish-mms group, and the service starts it with the privilieged group.

could you add the verbose switch to the service file
https://git.sailfishos.org/mer-core/mms-engine/blob/master/mms-engine/dbus-org.nemomobile.MmsEngine.service

probably in /etc/dbus-1/..... and get more logs thx

[Sagittarii]

Hello Adam.

Thanks for the quick feedback and tips.
Yes, sorry, I am in the small niche of Sailfish user that are also in the small niche of MMS users ;)
As said by Kabouik, it is the only common way to send pictures to anyone, and it is used regularly with my family and friends. I am French and I remember that Kabouik is too, it may be cultural...

First of all, as I see some commits in mer-core/mms-engine from last month, I forgot to say that I installed the latest image available on gitlab (https://gitlab.com/sailfishos-porters-ci/t5-ci/pipelines?scope=finished&page=1), which is 3 month old : https://gitlab.com/sailfishos-porters-ci/t5-ci/-/pipelines/143699483, and chose the "run-build-testing" version according to Kabouik 's guideline.
It looks like the last one that is only 1 month old has been deleted (pipeline #162784035), so I could use this one. I also didn't try any commands to update it yet, I only saw that the graphical update page of the settings says it is up to date.
If this could be related to the problem, I can try some update, otherwise will stay in this current config while trying to debug this.

Anyway, I found the dbus file at location "/usr/share/dbus-1/system-services/org.nemomobile.MmsEngine.service" that matches https://git.sailfishos.org/mer-core/mms-engine/blob/master/mms-engine/org.nemomobile.MmsEngine.service
and the service file at location "/usr/lib/systemd/system/dbus-org.nemomobile.MmsEngine.service" which matches with the previous commit https://git.sailfishos.org/mer-core/mms-engine/commit/c9a621100a44e72b0ddfff60940f72dae749d983 (updated last month about changing user to "radio").

I changed it to add the verbose flag as follows:

[Unit]
Description=MMS engine service

[Service]
Type=dbus
BusName=org.nemomobile.MmsEngine
ExecStart=/usr/sbin/mms-engine -o syslog -v
User=nemo
Group=privileged

Then running "journalctl -f" as root, I see the same trace as posted before when run as user, but I see some additional messages interleaved from ofono:

Aug 11 22:57:23 Pro1 mms-engine[14708]: [mms-connection-nemo] MessageCenter: http://mms.bouyguestelecom.fr/mms/wapenc
Aug 11 22:57:23 Pro1 mms-engine[14708]: [mms-connection-nemo] Activate /ril_0/context2
Aug 11 22:57:23 Pro1 mms-engine[14708]: [mms-ofono] Activating /ril_0/context2
Aug 11 22:57:23 Pro1 ofonod[3784]: Activating context: 1
Aug 11 22:57:23 Pro1 kernel: HTB: quantum of class 10010 is big. Consider r2q change.
Aug 11 22:57:23 Pro1 ofonod[3784]: Unexpected data call status 51
Aug 11 22:57:23 Pro1 mms-engine[14708]: [mms-ofono] ERROR! GDBus.Error:org.ofono.Error.Failed: Operation failed
Aug 11 22:57:23 Pro1 mms-engine[14708]: [mms-ofono] Giving up on /ril_0/context2
Aug 11 22:57:23 Pro1 mms-engine[14708]: [mms-dispatcher] XXXXXXXXXXXXXXX FAILED
Aug 11 22:57:23 Pro1 mms-engine[14708]: [mms-task] Send[8345] NEED_CONNECTION -> SLEEP
Aug 11 22:57:23 Pro1 mms-engine[14708]: [mms-connection-nemo] Connection XXXXXXXXXXXXXXX cancelled
Aug 11 22:57:23 Pro1 mms-engine[14708]: [mms-connection-nemo] Released /ril_0

The kernel line seems unrelated, as it appends some other times in the trace.
However, the line from ofonod are repeating every try.

So I am now trying to find details "Unexpected data call status 51" from the ofonod source code.

[Sagittarii]

Found it:
Messages comes from https://git.sailfishos.org/mer-core/ofono/blob/master/ofono/drivers/ril/ril_gprs_context.c#L404

	ril_error_init_failure(&error);
	if (ril_status != RIL_E_SUCCESS) {
		ofono_error("GPRS context: Reply failure: %s",
					ril_error_to_string(ril_status));
	} else if (!call) {
		ofono_error("Unexpected data call failure");
	} else if (call->status != PDP_FAIL_NONE) {
		ofono_error("Unexpected data call status %d", call->status);
		error.type = OFONO_ERROR_TYPE_CMS;
		error.error = call->status;
	} else if (!call->ifname) {
		/* Must have interface */
		ofono_error("GPRS context: No interface");
	} else {
		ofono_info("setting up data call");

		GASSERT(!gcd->calls_changed_id);
		ril_data_remove_handler(gcd->data, gcd->calls_changed_id);
		gcd->calls_changed_id =
			ril_data_add_calls_changed_handler(gcd->data,
				ril_gprs_context_call_list_changed, gcd);

		ril_gprs_context_set_active_call(gcd, call);
		ofono_gprs_context_set_interface(gc, call->ifname);
		ril_gprs_context_set_address(gc, call);
		ril_gprs_context_set_gateway(gc, call);
		ril_gprs_context_set_dns_servers(gc, call);
		ril_error_init_ok(&error);
	}

And the value 51 (printed as decimal, 0x33 as hexa) would be from this enum:
https://git.sailfishos.org/mer-core/ofono/blob/master/ofono/drivers/ril/ril_constants.h#L219

	PDP_FAIL_ONLY_IPV6_ALLOWED = 0x33,

What ?

In the settings "MMS access point" page, Protocol is set to "IP" (other choices are "IPv6" or "Dual"). By the way "Data Access Point" is also set to "IP" but shouldn't be related.

I see that during all my tests to try to make it work, I tried switching Authentication to "PAP" (or "CHAP" ? I didn't write down which it was), and didn't put it back as I thought...
Switching it back to "None" didn't help.
Switching to IPv6 seems to put some new traces of a new module [mms-task-http], like "ERROR! Failed to query IP address of rmnet_data3: Cannot assign requested address".

I was connected to wifi, so tried to disconnect from wifi, and as I was in the menu, I also cut the data connection and restarted it.
Then I was able to receive the MMS !
I switched back to "IP", and it still works for some other MMS not yet downloaded...

I reconnect to wifi, and it now fails.
Disconnect wifi, it still fails.

So, it looks like my settings are mostly correct.
There seems to be a huge thing with having the wifi connected.
And finally, it looks like the parameters are not updated as soon as I think there are, meaning I must have tested a lot of things that weren't really taken into account. I am not sure if it is updated when the mms-engine is started, which seems everytime a dbus request is made and the engine is stopped when it has finished, which may be quite long when there are some errors. Maybe it is when the data connexion is stopped/restarted only ? Maybe a bit of both ?

So, I have not yet understood all my mistakes, but seem to have found a way it works by setting it to IPv6 and disabling Wifi...

[Sagittarii]

I got to sent new MMS today from outside wifi coverage. It worked with the previous configuration (IPv6, Wifi activated but not connected).
It doesn't seem to be specific to the Pro1 port, and looks like general Sailfish/Operators issues.

I will keep an eye on this, and if I find something new (bug or solution), I will come back here.

So I am closing it for now. Thanks again for the help to troubleshoot and find a fix !