Warning `g_dbus_method_invocation_take_error: assertion 'error != NULL' failed` logged after failed VPN connection

[paulmenzel]

Debian sid/unstable with network-manager-l2tp 1.20.20-2 from 17 Feb 2025.

If a VPN connection cannot be established the warning below is logged:

g_dbus_method_invocation_take_error: assertion 'error != NULL' failed

Dez 31 12:19:51 abreu nm-l2tp-service[55931]: /sbin/ipsec up 837a96df-4fbc-4487-a2f5-152ff4e1ebd7
Dez 31 12:19:51 abreu charon[55957]: 12[CFG] received stroke: initiate '837a96df-4fbc-4487-a2f5-152ff4e1ebd7'
Dez 31 12:19:51 abreu charon[55957]: 14[IKE] initiating Main Mode IKE_SA 837a96df-4fbc-4487-a2f5-152ff4e1ebd7[1] to 141.14.220.175
Dez 31 12:19:51 abreu charon[55957]: 14[IKE] initiating Main Mode IKE_SA 837a96df-4fbc-4487-a2f5-152ff4e1ebd7[1] to 141.14.220.175
Dez 31 12:19:51 abreu charon[55957]: 14[ENC] generating ID_PROT request 0 [ SA V V V V V ]
Dez 31 12:19:51 abreu charon[55957]: 14[NET] sending packet: from 10.110.1.152[500] to 141.14.220.175[500] (532 bytes)
Dez 31 12:19:52 abreu charon[55957]: 15[NET] received packet: from 141.14.220.175[500] to 10.110.1.152[500] (204 bytes)
Dez 31 12:19:52 abreu charon[55957]: 15[ENC] parsed ID_PROT response 0 [ SA V V V V V V ]
Dez 31 12:19:52 abreu charon[55957]: 15[IKE] received NAT-T (RFC 3947) vendor ID
Dez 31 12:19:52 abreu charon[55957]: 15[IKE] received draft-ietf-ipsec-nat-t-ike-03 vendor ID
Dez 31 12:19:52 abreu charon[55957]: 15[IKE] received draft-ietf-ipsec-nat-t-ike-02\n vendor ID
Dez 31 12:19:52 abreu charon[55957]: 15[IKE] received draft-ietf-ipsec-nat-t-ike-02 vendor ID
Dez 31 12:19:52 abreu charon[55957]: 15[IKE] received draft-ietf-ipsec-nat-t-ike-00 vendor ID
Dez 31 12:19:52 abreu charon[55957]: 15[IKE] received DPD vendor ID
Dez 31 12:19:52 abreu charon[55957]: 15[CFG] selected proposal: IKE:AES_CBC_256/HMAC_SHA2_256_128/PRF_HMAC_SHA2_256/MODP_2048
Dez 31 12:19:52 abreu charon[55957]: 15[ENC] generating ID_PROT request 0 [ KE No NAT-D NAT-D ]
Dez 31 12:19:52 abreu charon[55957]: 15[NET] sending packet: from 10.110.1.152[500] to 141.14.220.175[500] (396 bytes)
Dez 31 12:19:52 abreu charon[55957]: 04[NET] received packet: from 141.14.220.175[500] to 10.110.1.152[500] (380 bytes)
Dez 31 12:19:52 abreu charon[55957]: 04[ENC] parsed ID_PROT response 0 [ KE No NAT-D NAT-D ]
Dez 31 12:19:52 abreu charon[55957]: 04[IKE] local host is behind NAT, sending keep alives
Dez 31 12:19:52 abreu charon[55957]: 04[ENC] generating ID_PROT request 0 [ ID HASH ]
Dez 31 12:19:52 abreu charon[55957]: 04[NET] sending packet: from 10.110.1.152[4500] to 141.14.220.175[4500] (92 bytes)
Dez 31 12:19:52 abreu charon[55957]: 07[NET] received packet: from 141.14.220.175[4500] to 10.110.1.152[4500] (72 bytes)
Dez 31 12:19:52 abreu charon[55957]: 07[ENC] parsed INFORMATIONAL_V1 request 2431277935 [ N(INVAL_IKE_SPI) ]
Dez 31 12:19:52 abreu charon[55957]: 07[ENC] ignoring unprotected INFORMATIONAL from 141.14.220.175
Dez 31 12:19:52 abreu charon[55957]: 07[IKE] message verification failed
Dez 31 12:19:52 abreu charon[55957]: 07[IKE] ignore malformed INFORMATIONAL request
Dez 31 12:19:52 abreu charon[55957]: 07[IKE] INFORMATIONAL_V1 request with message ID 2431277935 processing failed
Dez 31 12:19:54 abreu charon[55957]: 05[NET] received packet: from 141.14.220.175[500] to 10.110.1.152[500] (380 bytes)
Dez 31 12:19:54 abreu charon[55957]: 05[IKE] received retransmit of response with ID 0, but next request already sent
Dez 31 12:19:56 abreu charon[55957]: 08[IKE] sending retransmit 1 of request message ID 0, seq 3
Dez 31 12:19:56 abreu charon[55957]: 08[NET] sending packet: from 10.110.1.152[4500] to 141.14.220.175[4500] (92 bytes)
Dez 31 12:19:56 abreu charon[55957]: 10[NET] received packet: from 141.14.220.175[500] to 10.110.1.152[500] (380 bytes)
Dez 31 12:19:56 abreu charon[55957]: 10[IKE] received retransmit of response with ID 0, but next request already sent
Dez 31 12:19:56 abreu charon[55957]: 11[NET] received packet: from 141.14.220.175[4500] to 10.110.1.152[4500] (72 bytes)
Dez 31 12:19:56 abreu charon[55957]: 11[ENC] parsed INFORMATIONAL_V1 request 3385028202 [ N(INVAL_IKE_SPI) ]
Dez 31 12:19:56 abreu charon[55957]: 11[ENC] ignoring unprotected INFORMATIONAL from 141.14.220.175
Dez 31 12:19:56 abreu charon[55957]: 11[IKE] message verification failed
Dez 31 12:19:56 abreu charon[55957]: 11[IKE] ignore malformed INFORMATIONAL request
Dez 31 12:19:56 abreu charon[55957]: 11[IKE] INFORMATIONAL_V1 request with message ID 3385028202 processing failed
Dez 31 12:19:58 abreu charon[55957]: 13[NET] received packet: from 141.14.220.175[500] to 10.110.1.152[500] (380 bytes)
Dez 31 12:19:58 abreu charon[55957]: 13[IKE] received retransmit of response with ID 0, but next request already sent
Dez 31 12:20:00 abreu charon[55957]: 14[NET] received packet: from 141.14.220.175[500] to 10.110.1.152[500] (380 bytes)
Dez 31 12:20:00 abreu charon[55957]: 14[IKE] received retransmit of response with ID 0, but next request already sent
Dez 31 12:20:00 abreu NetworkManager[669]: <warn>  [1767162000.4483] vpn[0x55de167d7460,837a96df-4fbc-4487-a2f5-152ff4e1ebd7,"Molgen L2TP"]: failed to connect: 'Zeitüberschreitung wurde erreicht'
Dez 31 12:20:03 abreu charon[55957]: 04[IKE] sending retransmit 2 of request message ID 0, seq 3
Dez 31 12:20:03 abreu charon[55957]: 04[NET] sending packet: from 10.110.1.152[4500] to 141.14.220.175[4500] (92 bytes)
Dez 31 12:20:03 abreu charon[55957]: 07[NET] received packet: from 141.14.220.175[4500] to 10.110.1.152[4500] (72 bytes)
Dez 31 12:20:03 abreu charon[55957]: 07[ENC] parsed INFORMATIONAL_V1 request 3548930795 [ N(INVAL_IKE_SPI) ]
Dez 31 12:20:03 abreu charon[55957]: 07[ENC] ignoring unprotected INFORMATIONAL from 141.14.220.175
Dez 31 12:20:03 abreu charon[55957]: 07[IKE] message verification failed
Dez 31 12:20:03 abreu charon[55957]: 07[IKE] ignore malformed INFORMATIONAL request
Dez 31 12:20:03 abreu charon[55957]: 07[IKE] INFORMATIONAL_V1 request with message ID 3548930795 processing failed
Dez 31 12:20:07 abreu NetworkManager[56010]: Stopping strongSwan IPsec...
Dez 31 12:20:07 abreu charon[55957]: 00[DMN] SIGINT received, shutting down
Dez 31 12:20:07 abreu charon[55957]: 00[IKE] destroying IKE_SA in state CONNECTING without notification
Dez 31 12:20:07 abreu NetworkManager[55998]: initiating Main Mode IKE_SA 837a96df-4fbc-4487-a2f5-152ff4e1ebd7[1] to 141.14.220.175
Dez 31 12:20:07 abreu NetworkManager[55998]: generating ID_PROT request 0 [ SA V V V V V ]
Dez 31 12:20:07 abreu NetworkManager[55998]: sending packet: from 10.110.1.152[500] to 141.14.220.175[500] (532 bytes)
Dez 31 12:20:07 abreu NetworkManager[55998]: received packet: from 141.14.220.175[500] to 10.110.1.152[500] (204 bytes)
Dez 31 12:20:07 abreu NetworkManager[55998]: parsed ID_PROT response 0 [ SA V V V V V V ]
Dez 31 12:20:07 abreu NetworkManager[55998]: received NAT-T (RFC 3947) vendor ID
Dez 31 12:20:07 abreu NetworkManager[55998]: received draft-ietf-ipsec-nat-t-ike-03 vendor ID
Dez 31 12:20:07 abreu NetworkManager[55998]: received draft-ietf-ipsec-nat-t-ike-02\n vendor ID
Dez 31 12:20:07 abreu NetworkManager[55998]: received draft-ietf-ipsec-nat-t-ike-02 vendor ID
Dez 31 12:20:07 abreu NetworkManager[55998]: received draft-ietf-ipsec-nat-t-ike-00 vendor ID
Dez 31 12:20:07 abreu NetworkManager[55998]: received DPD vendor ID
Dez 31 12:20:07 abreu NetworkManager[55998]: selected proposal: IKE:AES_CBC_256/HMAC_SHA2_256_128/PRF_HMAC_SHA2_256/MODP_2048
Dez 31 12:20:07 abreu NetworkManager[55998]: generating ID_PROT request 0 [ KE No NAT-D NAT-D ]
Dez 31 12:20:07 abreu NetworkManager[55998]: sending packet: from 10.110.1.152[500] to 141.14.220.175[500] (396 bytes)
Dez 31 12:20:07 abreu NetworkManager[55998]: received packet: from 141.14.220.175[500] to 10.110.1.152[500] (380 bytes)
Dez 31 12:20:07 abreu NetworkManager[55998]: parsed ID_PROT response 0 [ KE No NAT-D NAT-D ]
Dez 31 12:20:07 abreu NetworkManager[55998]: local host is behind NAT, sending keep alives
Dez 31 12:20:07 abreu NetworkManager[55998]: generating ID_PROT request 0 [ ID HASH ]
Dez 31 12:20:07 abreu NetworkManager[55998]: sending packet: from 10.110.1.152[4500] to 141.14.220.175[4500] (92 bytes)
Dez 31 12:20:07 abreu NetworkManager[55998]: received packet: from 141.14.220.175[4500] to 10.110.1.152[4500] (72 bytes)
Dez 31 12:20:07 abreu NetworkManager[55998]: parsed INFORMATIONAL_V1 request 2431277935 [ N(INVAL_IKE_SPI) ]
Dez 31 12:20:07 abreu NetworkManager[55998]: ignoring unprotected INFORMATIONAL from 141.14.220.175
Dez 31 12:20:07 abreu NetworkManager[55998]: message verification failed
Dez 31 12:20:07 abreu NetworkManager[55998]: ignore malformed INFORMATIONAL request
Dez 31 12:20:07 abreu NetworkManager[55998]: INFORMATIONAL_V1 request with message ID 2431277935 processing failed
Dez 31 12:20:07 abreu NetworkManager[55998]: received packet: from 141.14.220.175[500] to 10.110.1.152[500] (380 bytes)
Dez 31 12:20:07 abreu NetworkManager[55998]: received retransmit of response with ID 0, but next request already sent
Dez 31 12:20:07 abreu NetworkManager[55998]: sending retransmit 1 of request message ID 0, seq 3
Dez 31 12:20:07 abreu NetworkManager[55998]: sending packet: from 10.110.1.152[4500] to 141.14.220.175[4500] (92 bytes)
Dez 31 12:20:07 abreu NetworkManager[55998]: received packet: from 141.14.220.175[500] to 10.110.1.152[500] (380 bytes)
Dez 31 12:20:07 abreu NetworkManager[55998]: received retransmit of response with ID 0, but next request already sent
Dez 31 12:20:07 abreu NetworkManager[55998]: received packet: from 141.14.220.175[4500] to 10.110.1.152[4500] (72 bytes)
Dez 31 12:20:07 abreu NetworkManager[55998]: parsed INFORMATIONAL_V1 request 3385028202 [ N(INVAL_IKE_SPI) ]
Dez 31 12:20:07 abreu NetworkManager[55998]: ignoring unprotected INFORMATIONAL from 141.14.220.175
Dez 31 12:20:07 abreu NetworkManager[55998]: message verification failed
Dez 31 12:20:08 abreu NetworkManager[55998]: ignore malformed INFORMATIONAL request
Dez 31 12:20:08 abreu NetworkManager[55998]: INFORMATIONAL_V1 request with message ID 3385028202 processing failed
Dez 31 12:20:08 abreu NetworkManager[55998]: received packet: from 141.14.220.175[500] to 10.110.1.152[500] (380 bytes)
Dez 31 12:20:08 abreu NetworkManager[55998]: received retransmit of response with ID 0, but next request already sent
Dez 31 12:20:08 abreu NetworkManager[55998]: received packet: from 141.14.220.175[500] to 10.110.1.152[500] (380 bytes)
Dez 31 12:20:08 abreu NetworkManager[55998]: received retransmit of response with ID 0, but next request already sent
Dez 31 12:20:08 abreu NetworkManager[55998]: sending retransmit 2 of request message ID 0, seq 3
Dez 31 12:20:08 abreu NetworkManager[55998]: sending packet: from 10.110.1.152[4500] to 141.14.220.175[4500] (92 bytes)
Dez 31 12:20:08 abreu NetworkManager[55998]: received packet: from 141.14.220.175[4500] to 10.110.1.152[4500] (72 bytes)
Dez 31 12:20:08 abreu NetworkManager[55998]: parsed INFORMATIONAL_V1 request 3548930795 [ N(INVAL_IKE_SPI) ]
Dez 31 12:20:08 abreu NetworkManager[55998]: ignoring unprotected INFORMATIONAL from 141.14.220.175
Dez 31 12:20:08 abreu NetworkManager[55998]: message verification failed
Dez 31 12:20:08 abreu NetworkManager[55998]: ignore malformed INFORMATIONAL request
Dez 31 12:20:08 abreu NetworkManager[55998]: INFORMATIONAL_V1 request with message ID 3548930795 processing failed
Dez 31 12:20:08 abreu NetworkManager[55998]: destroying IKE_SA in state CONNECTING without notification
Dez 31 12:20:08 abreu NetworkManager[55998]: establishing connection '837a96df-4fbc-4487-a2f5-152ff4e1ebd7' failed
Dez 31 12:20:08 abreu ipsec_starter[55956]: child 55957 (charon) has quit (exit code 0)
Dez 31 12:20:08 abreu ipsec_starter[55956]: 
Dez 31 12:20:08 abreu ipsec_starter[55956]: charon stopped after 200 ms
Dez 31 12:20:08 abreu ipsec_starter[55956]: ipsec starter stopped
Dez 31 12:20:08 abreu nm-l2tp-service[55931]: Could not establish IPsec connection.
Dez 31 12:20:08 abreu nm-l2tp-service[55931]: g_dbus_method_invocation_take_error: assertion 'error != NULL' failed

[dkosovic]

With the way Debian packages are built, C/C++ debugging assertions get enabled by default. The assertion 'error != NULL' message is just indicating the error string is not NULL (in the g_dbus_method_invocation_take_error() function in the GNOME Input/Output library). The error string has in fact a value of "Could not establish IPsec connection.". So that assertion output isn't significant for this issue.

The error log is indicating the strongswan charon daemon has an issue during main mode (i.e. phase 1, e.g. negotiating the algorithms), when it receives an INVAL_IKE_SPI error from the VPN server.

Assuming you are using an old VPN server that is still using weak or broken algorithms, you could try setting the following algorithms for phase 1 & 2 in the IPsec settings:

• phase 1 : 3des-sha1-modp1024!
• phase 2 : 3des-sha1!

Note the exclamation mark ! is significant with strongswan, as it overrides rather than appends to existing algorithms that are offered in the negotiations.

If it still doesn't work, you could switch from strongswan to libreswan by issuing the following:
sudo apt install libreswan

Be sure to remove the phase 1 & 2 settings. You may also need to tick the Disable PFS checkbox with libreswan in the IPsec settings if you are using an old VPN server that doesn't support Perfect Forward Secrecy.