feat: enhance IMS SMS handling with structured logging and payload extraction

2026-08-16 21:03:44 +08:00 · 2026-08-16 13:05:20 +08:00
parent f014628048
commit ffa0fd23b8
4 changed files with 302 additions and 20 deletions
@@ -616,7 +616,7 @@ func configureVoWiFiRuntime(
 			} else if deviceConfig.DeviceType == store.DeviceTypeWiFi410 {
 				adapter = nativeQMIAdapter
 			}
-			return newVoWiFiOrchestrator(deviceConfig, database, adapter)
+			return newVoWiFiOrchestrator(deviceConfig, database, adapter, logger)
 		},
 	})

@@ -715,6 +715,7 @@ func newVoWiFiOrchestrator(
 	deviceConfig store.Device,
 	database *store.Store,
 	adapter vowifiDeviceAdapter,
+	logger *slog.Logger,
 ) (*vowifi.Orchestrator, error) {
 	apn := deviceConfig.APN
 	if apn == "" {
@@ -725,6 +726,7 @@ func newVoWiFiOrchestrator(
 		return nil, fmt.Errorf("device %q IKE provider: %w", deviceConfig.ID, err)
 	}
 	imsProvider, err := ims.NewProvider(adapter, ims.Config{
+		Logger: logger,
 		// The userspace SWu data plane carries protected P-CSCF signalling over
 		// TCP by default. UK PLMN 234-10 exposes its P-CSCF over UDP/5060 on SWu.
 		Transport: "tcp",
@@ -8,6 +8,7 @@ import (
 	"encoding/hex"
 	"errors"
 	"fmt"
+	"log/slog"
 	"net"
 	"strconv"
 	"strings"
@@ -58,6 +59,9 @@ type Config struct {
 	// OnSMSStatus is invoked for an SMS-STATUS-REPORT received after a
 	// submission that requested a delivery report.
 	OnSMSStatus func(context.Context, ReceivedSMSStatus) error
+	// Logger receives structured IMS runtime diagnostics. Inbound SMS logs do
+	// not include message text or raw protocol payloads.
+	Logger *slog.Logger
 }

 // Provider implements vowifi.IMSProvider using a small RFC 3261 REGISTER
@@ -85,6 +89,9 @@ func NewProvider(aka vowifi.AKAProvider, config Config) (*Provider, error) {
 }

 func normalizeConfig(config Config) (Config, error) {
+	if config.Logger == nil {
+		config.Logger = slog.Default()
+	}
 	if config.Port == 0 {
 		config.Port = defaultSIPPort
 	}
@@ -2,10 +2,17 @@ package ims

 import (
 	"bufio"
+	"bytes"
 	"context"
+	"encoding/base64"
 	"encoding/hex"
 	"errors"
 	"fmt"
+	"io"
+	"log/slog"
+	"mime"
+	"mime/multipart"
+	"mime/quotedprintable"
 	"net"
 	"strconv"
 	"strings"
@@ -152,6 +159,11 @@ func (session *Session) readInboundTCP(connection net.Conn) {
 	for {
 		packet, err := readSIPPacket(reader)
 		if err != nil {
+			if !session.isClosed() && !errors.Is(err, io.EOF) && !errors.Is(err, net.ErrClosed) {
+				session.logInboundSMS(slog.LevelWarn, "IMS protected SIP packet read failed", nil,
+					"stage", "sip_parse", "transport", "tcp",
+					"remote", connection.RemoteAddr().String(), "error", err)
+			}
 			return
 		}
 		session.dispatchPacket(packet, func(response []byte) error {
@@ -174,6 +186,9 @@ func (session *Session) readProtectedUDP() {
 		}
 		packet, err := parseSIPPacket(buffer[:count])
 		if err != nil {
+			session.logInboundSMS(slog.LevelWarn, "IMS protected SIP packet parse failed", nil,
+				"stage", "sip_parse", "transport", "udp", "remote", remote.String(),
+				"packet_bytes", count, "error", err)
 			continue
 		}
 		session.dispatchPacket(packet, func(response []byte) error {
@@ -271,23 +286,44 @@ func (session *Session) handleSIPRequest(request *sipRequest, respond func([]byt
 	switch request.Method {
 	case "OPTIONS":
 	case "MESSAGE":
-		contentType := strings.ToLower(strings.TrimSpace(strings.SplitN(request.value("Content-Type"), ";", 2)[0]))
-		if contentType != smsContentType {
+		if !supportsSMSContentType(request.value("Content-Type")) {
 			status = 415
 		}
 	default:
 		status = 405
 	}
 	response, err := buildSIPResponse(request, status, session.fromTag)
-	if err == nil {
-		_ = respond(response)
+	if err != nil {
+		session.logInboundSMS(slog.LevelWarn, "IMS inbound SIP request response failed", request,
+			"stage", "sip_response_build", "error", err)
+	} else if err = respond(response); err != nil {
+		session.logInboundSMS(slog.LevelWarn, "IMS inbound SIP request response failed", request,
+			"stage", "sip_response_send", "sip_status", status, "error", err)
 	}
 	if status != 200 || request.Method != "MESSAGE" {
+		if request.Method == "MESSAGE" {
+			session.logInboundSMS(slog.LevelWarn, "IMS inbound SMS MESSAGE rejected", request,
+				"stage", "content_type", "sip_status", status)
+		}
 		return
 	}
+	session.logInboundSMS(slog.LevelInfo, "IMS inbound SMS MESSAGE received", request,
+		"stage", "sip_accepted")
 	go session.processSMSMessage(request)
 }

+func supportsSMSContentType(value string) bool {
+	mediaType, parameters, err := mime.ParseMediaType(strings.TrimSpace(value))
+	if err != nil {
+		return false
+	}
+	if strings.EqualFold(mediaType, smsContentType) {
+		return true
+	}
+	return strings.EqualFold(mediaType, "multipart/mixed") &&
+		strings.TrimSpace(parameters["boundary"]) != ""
+}
+
 func buildSIPResponse(request *sipRequest, status int, tag string) ([]byte, error) {
 	reason := map[int]string{200: "OK", 405: "Method Not Allowed", 415: "Unsupported Media Type", 488: "Not Acceptable Here"}[status]
 	if reason == "" {
@@ -325,24 +361,46 @@ func buildSIPResponse(request *sipRequest, status int, tag string) ([]byte, erro
 }

 func (session *Session) processSMSMessage(request *sipRequest) {
-	rpdu, err := parseRPDU(request.Body)
+	payload, payloadSource, err := extractSMSPayload(request)
 	if err != nil {
-		session.sendDeliveryReport(request, buildRPError(0, 95))
+		session.logInboundSMS(slog.LevelWarn, "IMS inbound SMS decode failed", request,
+			"stage", "mime", "error", err)
+		session.sendLoggedDeliveryReport(request, buildRPError(0, 95), "rp_error")
+		return
+	}
+	rpdu, err := parseRPDU(payload)
+	if err != nil {
+		reference := byte(0)
+		if len(payload) > 1 {
+			reference = payload[1]
+		}
+		session.logInboundSMS(slog.LevelWarn, "IMS inbound SMS decode failed", request,
+			"stage", "rpdu", "payload_source", payloadSource,
+			"rp_reference", int(reference), "payload_bytes", len(payload), "error", err)
+		session.sendLoggedDeliveryReport(request, buildRPError(reference, 95), "rp_error")
 		return
 	}
 	if rpdu.messageType != 1 { // RP-DATA, network to MS.
+		session.logInboundSMS(slog.LevelInfo, "IMS inbound SMS control message received", request,
+			"stage", "rpdu", "payload_source", payloadSource,
+			"rp_message_type", int(rpdu.messageType), "rp_reference", int(rpdu.reference))
 		return
 	}
 	message, err := device.DecodeSMSDeliverTPDU(rpdu.tpdu)
 	if err != nil {
-		session.sendDeliveryReport(request, buildRPError(rpdu.reference, 95))
+		session.logInboundSMS(slog.LevelWarn, "IMS inbound SMS decode failed", request,
+			"stage", "tpdu", "payload_source", payloadSource,
+			"rp_reference", int(rpdu.reference), "tpdu_bytes", len(rpdu.tpdu), "error", err)
+		session.sendLoggedDeliveryReport(request, buildRPError(rpdu.reference, 95), "rp_error")
 		return
 	}
 	receivedAt := time.Now().UTC()
 	callID := strings.TrimSpace(request.value("Call-ID"))
 	if message.Direction == device.SMSDirectionStatusReport {
 		if message.MessageReference == nil || message.StatusCode == nil {
-			session.sendDeliveryReport(request, buildRPError(rpdu.reference, 95))
+			session.logInboundSMS(slog.LevelWarn, "IMS inbound SMS status report is incomplete", request,
+				"stage", "tpdu", "rp_reference", int(rpdu.reference))
+			session.sendLoggedDeliveryReport(request, buildRPError(rpdu.reference, 95), "rp_error")
 			return
 		}
 		status := ReceivedSMSStatus{
@@ -366,14 +424,21 @@ func (session *Session) processSMSMessage(request *sipRequest) {
 			cancel()
 		}
 		if err != nil {
-			session.sendDeliveryReport(request, buildRPError(rpdu.reference, 22))
+			session.logInboundSMS(slog.LevelWarn, "IMS inbound SMS status persistence failed", request,
+				"stage", "status_callback", "rp_reference", int(rpdu.reference), "error", err)
+			session.sendLoggedDeliveryReport(request, buildRPError(rpdu.reference, 22), "rp_error")
 			return
 		}
-		session.sendDeliveryReport(request, []byte{0x02, rpdu.reference})
+		session.logInboundSMS(slog.LevelInfo, "IMS inbound SMS status report processed", request,
+			"stage", "status_callback", "rp_reference", int(rpdu.reference),
+			"status_code", *message.StatusCode)
+		session.sendLoggedDeliveryReport(request, []byte{0x02, rpdu.reference}, "rp_ack")
 		return
 	}
 	if message.Direction != device.SMSDirectionReceived {
-		session.sendDeliveryReport(request, buildRPError(rpdu.reference, 95))
+		session.logInboundSMS(slog.LevelWarn, "IMS inbound SMS has unexpected TPDU direction", request,
+			"stage", "tpdu", "rp_reference", int(rpdu.reference), "direction", message.Direction)
+		session.sendLoggedDeliveryReport(request, buildRPError(rpdu.reference, 95), "rp_error")
 		return
 	}
 	var serviceCenterTimestamp *time.Time
@@ -405,26 +470,130 @@ func (session *Session) processSMSMessage(request *sipRequest) {
 		cancel()
 	}
 	if err != nil {
-		session.sendDeliveryReport(request, buildRPError(rpdu.reference, 22))
+		session.logInboundSMS(slog.LevelWarn, "IMS inbound SMS persistence failed", request,
+			"stage", "sms_callback", "rp_reference", int(rpdu.reference), "error", err)
+		session.sendLoggedDeliveryReport(request, buildRPError(rpdu.reference, 22), "rp_error")
 		return
 	}
-	session.sendDeliveryReport(request, []byte{0x02, rpdu.reference})
+	session.logInboundSMS(slog.LevelInfo, "IMS inbound SMS processed", request,
+		"stage", "sms_callback", "payload_source", payloadSource,
+		"rp_reference", int(rpdu.reference), "encoding", message.Encoding,
+		"concatenated", message.Concat != nil)
+	session.sendLoggedDeliveryReport(request, []byte{0x02, rpdu.reference}, "rp_ack")
 }

-func (session *Session) sendDeliveryReport(request *sipRequest, report []byte) {
+func extractSMSPayload(request *sipRequest) ([]byte, string, error) {
+	if request == nil {
+		return nil, "", errors.New("ims: SMS MESSAGE is nil")
+	}
+	mediaType, parameters, err := mime.ParseMediaType(strings.TrimSpace(request.value("Content-Type")))
+	if err != nil {
+		return nil, "", fmt.Errorf("ims: parse SMS Content-Type: %w", err)
+	}
+	if strings.EqualFold(mediaType, smsContentType) {
+		payload, decodeErr := decodeSMSTransfer(request.Body, request.value("Content-Transfer-Encoding"))
+		return payload, smsContentType, decodeErr
+	}
+	if !strings.EqualFold(mediaType, "multipart/mixed") {
+		return nil, "", fmt.Errorf("ims: unsupported SMS Content-Type %q", mediaType)
+	}
+	boundary := strings.TrimSpace(parameters["boundary"])
+	if boundary == "" {
+		return nil, "", errors.New("ims: multipart SMS has no boundary")
+	}
+	reader := multipart.NewReader(bytes.NewReader(request.Body), boundary)
+	for {
+		part, nextErr := reader.NextRawPart()
+		if errors.Is(nextErr, io.EOF) {
+			break
+		}
+		if nextErr != nil {
+			return nil, "", fmt.Errorf("ims: read multipart SMS: %w", nextErr)
+		}
+		partType, _, parseErr := mime.ParseMediaType(strings.TrimSpace(part.Header.Get("Content-Type")))
+		if parseErr != nil || !strings.EqualFold(partType, smsContentType) {
+			_ = part.Close()
+			continue
+		}
+		body, readErr := io.ReadAll(part)
+		_ = part.Close()
+		if readErr != nil {
+			return nil, "", fmt.Errorf("ims: read multipart SMS payload: %w", readErr)
+		}
+		payload, decodeErr := decodeSMSTransfer(body, part.Header.Get("Content-Transfer-Encoding"))
+		return payload, "multipart/mixed", decodeErr
+	}
+	return nil, "", errors.New("ims: multipart MESSAGE omitted application/vnd.3gpp.sms payload")
+}
+
+func decodeSMSTransfer(body []byte, encoding string) ([]byte, error) {
+	switch strings.ToLower(strings.TrimSpace(encoding)) {
+	case "", "binary", "8bit":
+		return append([]byte(nil), body...), nil
+	case "base64":
+		decoded, err := io.ReadAll(base64.NewDecoder(base64.StdEncoding, bytes.NewReader(body)))
+		if err != nil {
+			return nil, fmt.Errorf("ims: decode base64 SMS payload: %w", err)
+		}
+		return decoded, nil
+	case "quoted-printable":
+		decoded, err := io.ReadAll(quotedprintable.NewReader(bytes.NewReader(body)))
+		if err != nil {
+			return nil, fmt.Errorf("ims: decode quoted-printable SMS payload: %w", err)
+		}
+		return decoded, nil
+	default:
+		return nil, fmt.Errorf("ims: unsupported SMS Content-Transfer-Encoding %q", encoding)
+	}
+}
+
+func (session *Session) logInboundSMS(level slog.Level, message string, request *sipRequest, attributes ...any) {
+	logger := slog.Default()
+	if session != nil && session.provider != nil && session.provider.config.Logger != nil {
+		logger = session.provider.config.Logger
+	}
+	base := []any{"device_id", session.request.DeviceID}
+	if request != nil {
+		base = append(base,
+			"call_id", strings.TrimSpace(request.value("Call-ID")),
+			"content_type", strings.TrimSpace(request.value("Content-Type")),
+			"body_bytes", len(request.Body),
+		)
+	}
+	logger.Log(context.Background(), level, message, append(base, attributes...)...)
+}
+
+func (session *Session) sendLoggedDeliveryReport(request *sipRequest, report []byte, reportType string) {
+	if err := session.sendDeliveryReport(request, report); err != nil {
+		session.logInboundSMS(slog.LevelWarn, "IMS inbound SMS delivery report failed", request,
+			"stage", "delivery_report", "report_type", reportType, "error", err)
+		return
+	}
+	session.logInboundSMS(slog.LevelDebug, "IMS inbound SMS delivery report sent", request,
+		"stage", "delivery_report", "report_type", reportType)
+}
+
+func (session *Session) sendDeliveryReport(request *sipRequest, report []byte) error {
 	target := firstURI(request.value("P-Asserted-Identity"))
 	if target == "" {
 		target = firstURI(request.value("From"))
 	}
 	if target == "" {
-		return
+		return errors.New("ims: SMS MESSAGE omitted a delivery-report target")
 	}
-	_, _ = session.sendSIPMessage(
+	response, err := session.sendSIPMessage(
 		context.Background(),
 		target,
 		report,
 		strings.TrimSpace(request.value("Call-ID")),
 	)
+	if err != nil {
+		return err
+	}
+	if response.StatusCode < 200 || response.StatusCode >= 300 {
+		return fmt.Errorf("ims: SMS delivery report returned SIP %d", response.StatusCode)
+	}
+	return nil
 }

 func (session *Session) SendSMS(ctx context.Context, request vowifi.SMSSubmitRequest) (vowifi.SMSSubmitResult, error) {
@@ -1,11 +1,14 @@
 package ims

 import (
+	"bytes"
 	"context"
 	"encoding/base64"
 	"errors"
 	"fmt"
+	"mime/multipart"
 	"net"
+	"net/textproto"
 	"strings"
 	"testing"
 	"time"
@@ -100,6 +103,89 @@ func TestRuntimeSecurityHeaders(t *testing.T) {
 	}
 }

+func TestExtractSMSPayload(t *testing.T) {
+	rpdu := []byte{0x01, 0x2a, 0x00, 0x00, 0x03, 0x04, 0x00, 0x00}
+	tests := []struct {
+		name        string
+		request     *sipRequest
+		wantSource  string
+		wantPayload []byte
+	}{
+		{
+			name: "direct binary",
+			request: &sipRequest{Headers: map[string][]string{
+				"content-type":              {smsContentType + "; charset=binary"},
+				"content-transfer-encoding": {"binary"},
+			}, Body: rpdu},
+			wantSource:  smsContentType,
+			wantPayload: rpdu,
+		},
+		{
+			name:        "multipart base64",
+			request:     multipartSMSRequest(t, rpdu),
+			wantSource:  "multipart/mixed",
+			wantPayload: rpdu,
+		},
+	}
+	for _, test := range tests {
+		t.Run(test.name, func(t *testing.T) {
+			payload, source, err := extractSMSPayload(test.request)
+			if err != nil {
+				t.Fatalf("extractSMSPayload() error = %v", err)
+			}
+			if source != test.wantSource || !bytes.Equal(payload, test.wantPayload) {
+				t.Fatalf("extractSMSPayload() = (%x, %q), want (%x, %q)",
+					payload, source, test.wantPayload, test.wantSource)
+			}
+		})
+	}
+}
+
+func TestSupportsSMSContentType(t *testing.T) {
+	for _, test := range []struct {
+		value string
+		want  bool
+	}{
+		{smsContentType, true},
+		{"Application/Vnd.3gpp.Sms; charset=binary", true},
+		{`multipart/mixed; boundary="vodafone-boundary"`, true},
+		{"multipart/mixed", false},
+		{"text/plain", false},
+	} {
+		if got := supportsSMSContentType(test.value); got != test.want {
+			t.Errorf("supportsSMSContentType(%q) = %v, want %v", test.value, got, test.want)
+		}
+	}
+}
+
+func multipartSMSRequest(t *testing.T, payload []byte) *sipRequest {
+	t.Helper()
+	var body bytes.Buffer
+	writer := multipart.NewWriter(&body)
+	if err := writer.SetBoundary("vodafone-boundary"); err != nil {
+		t.Fatal(err)
+	}
+	header := make(textproto.MIMEHeader)
+	header.Set("Content-Type", smsContentType)
+	header.Set("Content-Transfer-Encoding", "base64")
+	part, err := writer.CreatePart(header)
+	if err != nil {
+		t.Fatal(err)
+	}
+	if _, err = part.Write([]byte(base64.StdEncoding.EncodeToString(payload))); err != nil {
+		t.Fatal(err)
+	}
+	if err = writer.Close(); err != nil {
+		t.Fatal(err)
+	}
+	return &sipRequest{
+		Headers: map[string][]string{
+			"content-type": {`multipart/mixed; boundary="vodafone-boundary"`},
+		},
+		Body: body.Bytes(),
+	}
+}
+
 func TestSessionSendsSMSOverIMS(t *testing.T) {
 	listener, err := net.ListenUDP("udp", &net.UDPAddr{IP: net.ParseIP("127.0.0.1")})
 	if err != nil {
@@ -202,6 +288,24 @@ func serveInboundSMS(listener *net.UDPConn, nonce string, readyForClose chan<- s
 	}
 	rpdu := []byte{0x01, 0x2a, 0x00, 0x00, byte(len(tpdu))}
 	rpdu = append(rpdu, tpdu...)
+	var messageBody bytes.Buffer
+	mimeWriter := multipart.NewWriter(&messageBody)
+	if err = mimeWriter.SetBoundary("vodafone-delivery"); err != nil {
+		return err
+	}
+	mimeHeader := make(textproto.MIMEHeader)
+	mimeHeader.Set("Content-Type", smsContentType)
+	mimeHeader.Set("Content-Transfer-Encoding", "binary")
+	mimePart, createErr := mimeWriter.CreatePart(mimeHeader)
+	if createErr != nil {
+		return createErr
+	}
+	if _, err = mimePart.Write(rpdu); err != nil {
+		return err
+	}
+	if err = mimeWriter.Close(); err != nil {
+		return err
+	}
 	request := []byte(strings.Join([]string{
 		"MESSAGE sip:[email protected] SIP/2.0",
 		"Via: SIP/2.0/UDP " + listener.LocalAddr().String() + ";branch=z9hG4bKdeliver",
@@ -210,10 +314,10 @@ func serveInboundSMS(listener *net.UDPConn, nonce string, readyForClose chan<- s
 		"P-Asserted-Identity: <sip:[email protected]>",
 		"Call-ID: network-deliver-1",
 		"CSeq: 1 MESSAGE",
-		"Content-Type: application/vnd.3gpp.sms",
-		fmt.Sprintf("Content-Length: %d", len(rpdu)), "", "",
+		`Content-Type: multipart/mixed; boundary="vodafone-delivery"`,
+		fmt.Sprintf("Content-Length: %d", messageBody.Len()), "", "",
 	}, "\r\n"))
-	request = append(request, rpdu...)
+	request = append(request, messageBody.Bytes()...)
 	if _, err = listener.WriteToUDP(request, remote); err != nil {
 		return err
 	}