Non3GPP Test: N3IWF - UE interaction Error

kueili-huang · August 11, 2020, 9:35am

Hi,

The free5gc of version v3.0.3 has just been installed.
The testing followed is just going fine except the Non3GPP testing.

The Non3GPP testing error happened during the TestNon3GPPUE procedure, showing that the IKE module of N3IWF NF runs into an error with the cause that EAP is nil.

The detailed wireshark pcap and the message log have been attached in the 7z file.

question.7z (75.1 KB)

Please help me to figure out the cause and provide a solution.

free5GC · August 11, 2020, 12:47pm

This is the same issue. We’re now fixing it.

Thanks for your report!

github.com/free5gc/free5gc

[Bugs] failed to ./test.sh TestNon3GPP

opened 04:34AM - 30 Jul 20 UTC

closed 12:55AM - 29 Sep 20 UTC

s5uishida

N3IWF

## Describe the bug(??) When running `./test.sh TestNon3GPP` with the settings …of free5GC as-is, the following error was output. ``` ERRO[2020-07-30T04:19:05Z]/ike/handler/handler.go:428 free5gc/src/n3iwf/ike/handler.HandleIKEAUTH() [IKE] The initiator identification field is nil N3IWF=IKE ``` This is the last line of the log below. ``` ... TestNon3GPPUE: non3gpp_test.go:678: Get IDr TestNon3GPPUE: non3gpp_test.go:682: Get CERT TestNon3GPPUE: non3gpp_test.go:680: Get AUTH TestNon3GPPUE: non3gpp_test.go:685: Get EAP INFO[2020-07-30T04:19:05Z]/root/free5gc/src/n3iwf/ike/message/message.go:70 free5gc/src/n3iwf/ike/message.EncodePayload() Encoding IKE payloads N3IWF=IKE INFO[2020-07-30T04:19:05Z]/root/free5gc/src/n3iwf/ike/message/message.go:1285 free5gc/src/n3iwf/ike/message.(*EAP).marshal() [IKE][EAP] marshal(): Start marshalling N3IWF=IKE INFO[2020-07-30T04:19:05Z]/root/free5gc/src/n3iwf/ike/message/message.go:1484 free5gc/src/n3iwf/ike/message.(*EAPExpanded).marshal() [IKE][EAP][Expanded] marshal(): Start marshalling N3IWF=IKE INFO[2020-07-30T04:19:05Z]/root/free5gc/src/n3iwf/ike/message/message.go:32 free5gc/src/n3iwf/ike/message.Encode() Encoding IKE message N3IWF=IKE INFO[2020-07-30T04:19:05Z]/root/free5gc/src/n3iwf/ike/message/message.go:35 free5gc/src/n3iwf/ike/message.Encode() [IKE] Start encoding IKE message N3IWF=IKE INFO[2020-07-30T04:19:05Z]/root/free5gc/src/n3iwf/ike/message/message.go:70 free5gc/src/n3iwf/ike/message.EncodePayload() Encoding IKE payloads N3IWF=IKE INFO[2020-07-30T04:19:05Z]/root/free5gc/src/n3iwf/ike/message/message.go:1180 free5gc/src/n3iwf/ike/message.(*Encrypted).marshal() [IKE][Encrypted] marshal(): Start marshalling N3IWF=IKE INFO[2020-07-30T04:19:05Z]/root/free5gc/src/n3iwf/ike/message/message.go:32 free5gc/src/n3iwf/ike/message.Encode() Encoding IKE message N3IWF=IKE INFO[2020-07-30T04:19:05Z]/root/free5gc/src/n3iwf/ike/message/message.go:35 free5gc/src/n3iwf/ike/message.Encode() [IKE] Start encoding IKE message N3IWF=IKE INFO[2020-07-30T04:19:05Z]/root/free5gc/src/n3iwf/ike/message/message.go:70 free5gc/src/n3iwf/ike/message.EncodePayload() Encoding IKE payloads N3IWF=IKE INFO[2020-07-30T04:19:05Z]/root/free5gc/src/n3iwf/ike/message/message.go:1180 free5gc/src/n3iwf/ike/message.(*Encrypted).marshal() [IKE][Encrypted] marshal(): Start marshalling N3IWF=IKE INFO[2020-07-30T04:19:05Z]/ike/message/message.go:103 free5gc/src/n3iwf/ike/message.Decode() Decoding IKE message N3IWF=IKE TRAC[2020-07-30T04:19:05Z]/ike/message/message.go:104 free5gc/src/n3iwf/ike/message.Decode() Received IKE message: 00000000 00 00 00 00 00 01 e0 f3 2e c5 92 99 79 8a ab 59 |............y..Y| 00000010 2e 20 23 08 00 00 00 02 00 00 00 9c 30 00 00 80 |. #.........0...| 00000020 e7 a9 48 68 dd d9 9a 84 54 f4 08 30 42 b2 c7 b4 |..Hh....T..0B...| 00000030 d6 70 df d0 bd 0c d5 a8 96 6a 94 5c 1b f8 63 ee |.p.......j.\..c.| 00000040 75 c7 5b e9 32 11 8e 36 ba 22 c0 93 31 16 41 46 |u.[.2..6."..1.AF| 00000050 9e 45 4c b0 a4 b1 02 35 58 26 ce b5 10 a4 a7 43 |.EL....5X&.....C| 00000060 37 e2 ae 98 84 73 3c 4e 53 ea bf 92 37 67 a4 be |7....s<NS...7g..| 00000070 e9 fe ad c7 1f a8 d7 b4 61 6a b3 3f a3 00 68 1a |........aj.?..h.| 00000080 88 42 26 52 2b 24 bc 23 cb 1f 7f ca 0f 55 42 0a |.B&R+$.#.....UB.| 00000090 88 d9 e5 23 c1 50 25 91 70 39 b5 0c |...#.P%.p9..| N3IWF=IKE INFO[2020-07-30T04:19:05Z]/ike/message/message.go:142 free5gc/src/n3iwf/ike/message.DecodePayload() Decoding IKE payloads N3IWF=IKE TRAC[2020-07-30T04:19:05Z]/ike/message/message.go:148 free5gc/src/n3iwf/ike/message.DecodePayload() [IKE] DecodePayload(): Decode 1 payload N3IWF=IKE INFO[2020-07-30T04:19:05Z]/ike/message/message.go:1190 free5gc/src/n3iwf/ike/message.(*Encrypted).unmarshal() [IKE][Encrypted] unmarshal(): Start unmarshalling received bytes N3IWF=IKE TRAC[2020-07-30T04:19:05Z]/ike/message/message.go:1191 free5gc/src/n3iwf/ike/message.(*Encrypted).unmarshal() [IKE][Encrypted] unmarshal(): Payload length 124 bytes N3IWF=IKE INFO[2020-07-30T04:19:05Z]/ike/handler/handler.go:291 free5gc/src/n3iwf/ike/handler.HandleIKEAUTH() [IKE] Handle IKE_AUTH N3IWF=IKE INFO[2020-07-30T04:19:05Z]/ike/message/message.go:32 free5gc/src/n3iwf/ike/message.Encode() Encoding IKE message N3IWF=IKE INFO[2020-07-30T04:19:05Z]/ike/message/message.go:35 free5gc/src/n3iwf/ike/message.Encode() [IKE] Start encoding IKE message N3IWF=IKE INFO[2020-07-30T04:19:05Z]/ike/message/message.go:70 free5gc/src/n3iwf/ike/message.EncodePayload() Encoding IKE payloads N3IWF=IKE INFO[2020-07-30T04:19:05Z]/ike/message/message.go:1180 free5gc/src/n3iwf/ike/message.(*Encrypted).marshal() [IKE][Encrypted] marshal(): Start marshalling N3IWF=IKE TRAC[2020-07-30T04:19:05Z]/ike/message/message.go:60 free5gc/src/n3iwf/ike/message.Encode() Encoded 156 bytes N3IWF=IKE TRAC[2020-07-30T04:19:05Z]/ike/message/message.go:61 free5gc/src/n3iwf/ike/message.Encode() IKE message data: 00000000 00 00 00 00 00 01 e0 f3 2e c5 92 99 79 8a ab 59 |............y..Y| 00000010 2e 20 23 08 00 00 00 02 00 00 00 9c 30 00 00 80 |. #.........0...| 00000020 e7 a9 48 68 dd d9 9a 84 54 f4 08 30 42 b2 c7 b4 |..Hh....T..0B...| 00000030 d6 70 df d0 bd 0c d5 a8 96 6a 94 5c 1b f8 63 ee |.p.......j.\..c.| 00000040 75 c7 5b e9 32 11 8e 36 ba 22 c0 93 31 16 41 46 |u.[.2..6."..1.AF| 00000050 9e 45 4c b0 a4 b1 02 35 58 26 ce b5 10 a4 a7 43 |.EL....5X&.....C| 00000060 37 e2 ae 98 84 73 3c 4e 53 ea bf 92 37 67 a4 be |7....s<NS...7g..| 00000070 e9 fe ad c7 1f a8 d7 b4 61 6a b3 3f a3 00 68 1a |........aj.?..h.| 00000080 88 42 26 52 2b 24 bc 23 cb 1f 7f ca 0f 55 42 0a |.B&R+$.#.....UB.| 00000090 88 d9 e5 23 c1 50 25 91 70 39 b5 0c |...#.P%.p9..| N3IWF=IKE TRAC[2020-07-30T04:19:05Z]/ike/handler/security.go:170 free5gc/src/n3iwf/ike/handler.VerifyIKEChecksum() Calculated checksum: 00000000 88 d9 e5 23 c1 50 25 91 70 39 b5 0c |...#.P%.p9..| Received checksum: 00000000 88 d9 e5 23 c1 50 25 91 70 39 b5 0c |...#.P%.p9..| N3IWF=IKE TRAC[2020-07-30T04:19:05Z]/ike/handler/security.go:238 free5gc/src/n3iwf/ike/handler.DecryptMessage() Decrypted content: 00000000 00 00 00 59 02 41 00 55 fe 00 28 af 00 00 00 03 |...Y.A.U..(.....| 00000010 02 00 00 24 01 07 00 02 f8 39 ca fe 00 04 02 00 |...$.....9......| 00000020 04 02 05 00 03 02 f8 39 03 0e 00 0c 00 04 01 01 |.......9........| 00000030 02 03 00 04 01 11 22 33 00 1f 7e 00 41 19 00 0c |......"3..~.A...| 00000040 01 02 f8 39 f0 ff 00 00 00 00 47 78 10 01 07 2e |...9......Gx....| 00000050 08 80 20 00 00 00 00 00 00 07 07 07 07 07 07 06 |.. .............| N3IWF=IKE TRAC[2020-07-30T04:19:05Z]/ike/handler/security.go:243 free5gc/src/n3iwf/ike/handler.DecryptMessage() Decrypted content with out padding: 00000000 00 00 00 59 02 41 00 55 fe 00 28 af 00 00 00 03 |...Y.A.U..(.....| 00000010 02 00 00 24 01 07 00 02 f8 39 ca fe 00 04 02 00 |...$.....9......| 00000020 04 02 05 00 03 02 f8 39 03 0e 00 0c 00 04 01 01 |.......9........| 00000030 02 03 00 04 01 11 22 33 00 1f 7e 00 41 19 00 0c |......"3..~.A...| 00000040 01 02 f8 39 f0 ff 00 00 00 00 47 78 10 01 07 2e |...9......Gx....| 00000050 08 80 20 00 00 00 00 00 00 |.. ......| N3IWF=IKE INFO[2020-07-30T04:19:05Z]/ike/message/message.go:142 free5gc/src/n3iwf/ike/message.DecodePayload() Decoding IKE payloads N3IWF=IKE TRAC[2020-07-30T04:19:05Z]/ike/message/message.go:148 free5gc/src/n3iwf/ike/message.DecodePayload() [IKE] DecodePayload(): Decode 1 payload N3IWF=IKE INFO[2020-07-30T04:19:05Z]/ike/message/message.go:1307 free5gc/src/n3iwf/ike/message.(*EAP).unmarshal() [IKE][EAP] unmarshal(): Start unmarshalling received bytes N3IWF=IKE TRAC[2020-07-30T04:19:05Z]/ike/message/message.go:1308 free5gc/src/n3iwf/ike/message.(*EAP).unmarshal() [IKE][EAP] unmarshal(): Payload length 85 bytes N3IWF=IKE TRAC[2020-07-30T04:19:05Z]/ike/message/message.go:1311 free5gc/src/n3iwf/ike/message.(*EAP).unmarshal() [IKE][EAP] unmarshal(): Unmarshal 1 EAP N3IWF=IKE INFO[2020-07-30T04:19:05Z]/ike/message/message.go:1505 free5gc/src/n3iwf/ike/message.(*EAPExpanded).unmarshal() [IKE][EAP][Expanded] unmarshal(): Start unmarshalling received bytes N3IWF=IKE TRAC[2020-07-30T04:19:05Z]/ike/message/message.go:1506 free5gc/src/n3iwf/ike/message.(*EAPExpanded).unmarshal() [IKE][EAP][Expanded] unmarshal(): Payload length 81 bytes N3IWF=IKE ERRO[2020-07-30T04:19:05Z]/ike/handler/handler.go:428 free5gc/src/n3iwf/ike/handler.HandleIKEAUTH() [IKE] The initiator identification field is nil N3IWF=IKE ``` It seems to have failed in the `// IKE_AUTH - EAP exchange` phase after `non3gpp_test.go:689` line. Could you know what is happened? Here, it is always reproduced. If you need any other information, please let me know. Many thanks in advance. ## Environment (please complete the following information): - free5GC Version [v3.0.3] - OS: [Ubuntu 18.04 Server] - Kernel version [5.0.0-23-generic] - go version [1.14.4 linux/amd64] - c compiler version (Option) [gcc version 7.5.0] ### PCAP File [free5gc.pcap.gz](https://github.com/free5gc/free5gc/files/4998771/free5gc.pcap.gz) ### Log File I will also attach `free5gc/log/*`. [log_20200730.tar.gz](https://github.com/free5gc/free5gc/files/4998774/log_20200730.tar.gz)