Freeradius的radacct数据表中没有记账数据的解决办法-CSDN博客

本文链接：https://blog.csdn.net/inthesun29/article/details/107563354

因为工作中需要将Freeradius与某厂商的BRAS对接，前期已经将RADIUS的认证功能测试完成，但是发现用户拨号上线以后，Freeradius的radacct表中没有任何记录。当时因为主要集中精力在测试认证方面的问题，这个就没太在意。到后来从Mikrotik的ROS切过来了一部分测试帐号过来测试，发现ROS下的用户在radacct表中有记账记录，这就说明Freeradius本身的记账功能应该是正常的。当前期认证测试结束以后，这个问题变得尤为突出，因为随后系统会根据记账记录来将到期用户踢下线。现在需要解决掉这个问题了。
按照前面说的，ROS的用户记账信息正常，而我们这台BRAS没有记账信息，首先我怀疑是这台设备的记账配置（端口1813）没有做，或者做的配置有问题，导致设备没有发送记账报文。遂联系厂家工程师检查。经过厂家检查，没有发现配置上有问题，通过打开调试模式，设备也有正常的记账报文发送，并且通过设备的radius ping，也可以正常ping通radius服务器，这个时候每ping一次，在radacct表中都会产生一条记录。通过这样的排查和测试，证明了设备本身也没有问题。这就越来越奇怪了，到底问题出在哪里？
接下来，我觉得需要在radius服务器端抓包做测试了，看看记账报文（Accounting-Request）是否能到达radius服务器，radius服务器是否对报文有正确的响应（Accounting-Response）。服务器端我们使用如下命令开始抓包：

sudo tcpdump -A -w pppoe.cap udp port 1813

抓包过程中，我们记录了账号正常上下线产生的记账报文和在BRAS端通过radius ping产生的记账报文，以便分析两者有什么不同，为什么前者在数据库中没有记录，而后者有记录。而且抓的时间也比较长，这样能看到BRAS记账报文的重试机制。在少量用户的情况下，这样抓包也不会有很大的数据量。
抓包完成以后，我们通过Wireshark，对抓到的数据包进行分析，通过分析我们有了新的发现，radius服务器端能收到BRAS发来的记账报文，问题也出现了：radius ping的报文（Accounting-Request）可以立即得到服务器的回复（Accounting-Response），但是正常拨号上线的记账报文（Accounting-Request）一直在反复发送，radius服务器没有任何响应，每次用户上线，都会产生一条Accounting-Request报文，服务器没有响应，3秒以后会重新发送，重新发送的报文仍然没有得到服务器的响应，就继续在3秒钟以后重试，当重试3次以后（加上第一次一共4次），便不再发送记账报文，等待10分钟以后，再次开始尝试向服务器发送记账报文，如此循环下去。如下图：
在这里插入图片描述
通过抓包，我们逐步缩小了出现问题根源的范围，按照目前的线索，只能是freeradius本身出现了问题，那么到底是freeradius哪里出现了问题？
首先，我们查看了freeradius的日志，里面没有什么有用的信息，然后到freeradius的配置文件目录中，看看各个配置文件是否存在配置错误，也没有发现问题。不过我们在查看freeradius的日志文件的时候，发现了一些线索。/var/log/freeradius存放着radius的日志文件，里面还有一个叫radacct的目录，看文件夹的名字和数据库中数据表的名字一样，我肯定这个文件夹和记账有关，进入文件夹以后，里面的日志按照NAS（BRAS）的IP地址放在不同的目录中，进入对应的目录，就会看到按日期存放的记账信息日志，打开我们做测试当天的日志，大概内容如下：

Wed Jun 24 15:30:16 2020
	Service-Type = Framed-User
	Framed-Protocol = PPP
	NAS-Port = 15740308
	NAS-Port-Type = Ethernet
	User-Name = "000000001"
	Calling-Station-Id = "FF:FF:FF:FF:FF:FF"
	Called-Station-Id = "2000_cvlan199"
	NAS-Port-Id = "2000_cvlan199"
	Acct-Session-Id = "81602d92"
	Framed-IP-Address = 10.10.10.232
	Acct-Authentic = RADIUS
	Event-Timestamp = "Jun 24 2020 15:29:32 CST"
	Acct-Status-Type = Start
	NAS-Identifier = "MikroTik"
	Acct-Delay-Time = 0
	NAS-IP-Address = 172.24.0.1
	Tmp-String-9 = "ai:"
	Acct-Unique-Session-Id = "dded6743785a4186f5d630ee543c8823"
	Timestamp = 1592983816

Thu Jul 23 11:36:00 2020
        ZTE-Access-Domain = "dial"
        User-Name = "test"
        NAS-Port-Id = "Agent-Circuit-Id Not Present"
        NAS-Port = 4278220749
        Calling-Station-Id = "FF:FF:FF:FF:FF:FF"
        NAS-Identifier = "XX-XX-X0000-1"
        Acct-Session-Id = "02352747ppp19fc94103eb7d41f006d"
        NAS-IP-Address = 172.24.0.2
        Acct-Delay-Time = 3633
        Acct-Status-Type = Start
        Event-Timestamp = "Jul 23 2020 10:35:27 CST"
        Framed-IP-Address = 10.10.10.2
        Acct-Authentic = RADIUS
        NAS-Port-Type = Ethernet
        Service-Type = Framed-User
        Framed-Protocol = PPP
        Tmp-String-9 = "ai:"
        Acct-Unique-Session-Id = "45580f28afe73ea1bec1b53d0a524c7a"
        Timestamp = 1595475360

Thu Jul 23 11:51:08 2020
        User-Name = "test"
        NAS-Identifier = "XX-XX-X0000-1"
        Acct-Session-Id = "200723035108---pingacct0002"
        NAS-IP-Address = 172.24.0.2
        Acct-Delay-Time = 0
        Acct-Status-Type = Start
        NAS-Port-Type = Async
        Event-Timestamp = "Jul 23 2020 11:51:08 CST"
        Tmp-String-9 = "ai:"
        Acct-Unique-Session-Id = "6eaf30d23890c9d4ead01f5eb709133c"
        Timestamp = 1595476268

我们看到了所有radius服务器收到的记账报文。这说明radius服务器收到了所有的报文并在日志文件中进行了记录，但是对于某些报文却因为某些原因没有做响应。
按照目前发现的线索，radius服务器对收到的记账报文，首先会将其写入到日志文件中，然后肯定会写入radacct数据表中，写入数据库的SQL语句在/etc/freeradius/3.0/mods-config/sql/main/mysql/queries.conf文件中（这是我在查找配置文件是否有问题的时候发现的）。既然能正常将报文写入日志文件，那么会不会在写入数据库这一步的时候发生了问题？比如压根儿就没有写入数据库的操作或者写入时候发生异常没有成功将报文写入数据表，由此造成了对记账报文操作的中断？这应该是写入日志文件以后的下一步操作，那么我打算来检查一下。
这一步我们需要查看mariadb的日志，以便证实数据库是否收到了SQL命令进行了数据插入INSERT操作，查看了mariadb的日志环境变量：

>show global variables like '%general_log%';
>+------------------+----------------------+
| Variable_name    | Value                |
+------------------+----------------------+
| general_log      | OFF                  |
| general_log_file | xxxxxxxxxxxxxxxx.log |
+------------------+----------------------+
2 rows in set

这里我们看到mariadb的日志记录并没有打开，我们需要先将它打开：

>set global general_log=1;

再来查看一下环境变量：

>show global variables like '%general_log%';

+------------------+----------------------+
| Variable_name    | Value                |
+------------------+----------------------+
| general_log      | ON                   |
| general_log_file | xxxxxxxxxxxxxxxx.log |
+------------------+----------------------+
2 rows in set

日志记录已经被打开了，接下来，我们重新做拨号测试以便在日志文件中能看到对应的SQL命令。
在/var/lib/mysql目录中找到日志文件，打开它：

cat xxxxxxxxxxxxxxxx.log

或者用nano打开：

nano xxxxxxxxxxxxxxxx.log

在文件中，我们看到了类似如下的SQL语句：

INSERT INTO radacct (acctsessionid,acctuniqueid,username,realm,nasipaddress,nasportid,nasporttype,acctstarttime,acctupdatetime,acctstoptime,acctsessiontime,acctauthentic,connectinfo_start,connectinfo_stop,acctinputoctets,acctoutputoctets,calledstationid,callingstationid,acctterminatecause,servicetype,framedprotocol,framedipaddress,framedipv6address,framedipv6prefix,framedinterfaceid,delegatedipv6prefix) VALUES ('09062847ppp168b94103eb7d41f007c', 'd29f7a1853ed8a392de73fbc97efebec', 'test', '', '10.10.0.2', 'Agent-Circuit-Id Not Present', 'Ethernet', FROM_UNIXTIME(1595503588 - 8400), FROM_UNIXTIME(1595503588), NULL, 8400, 'RADIUS', '', '', '0' << 32 | '6632431', '0' << 32 | '25349731', '', 'ff:ff:ff:ff:ff:ff', '', 'Framed-User', 'PPP', '10.10.120.2', '', '', '', '');

我们将这条语句复制出来，在mariadb命令行、phpmyadmin或者Navicat中执行这条SQL命令（当然，为了以防万一，可以新建一个测试数据库，将radius数据库中radacct数据表的结构复制到测试数据库中，我们所有的测试都在测试数据库中去做，以免误操作造成不可预料的后果。）
当我们执行了这条命令以后，数据库出下如下提示：

1406 - Data too long for column 'nasportid' at row 1

意思是这条命令向nasportid字段插入的数据过长了，数据自然也没有插入数据表中去，到这里，我们发现果然是因为数据库数据没有正常插入造成对记账报文响应过程的中断。
我们查看radacct数据表的结构，发现字段nasportid的类型是varchar(15)，只能存放15个字符，而上面那条SQL命令中要向nasportid字段插入的字符串一共有28个字符，这样就造成了命令执行失败。到这里我们找到了问题的根源。
那么解决办法呢？解决办法有两种途径：
1、让NAS或者BRAS发送的记账请求报文中NAS-Port-Id属性的值变短，限制在15个字符之内。很多厂家的BRAS设备可以通过类似nas-port-id-format的命令来更改NAS-Port-Id的格式，有可能能将属性值限制在15个字符之内。
2、修改radacct数据表的结构，将nasportid字段的类型从varchar(15)改为varchar(30)或者大于30的其他长度，根据具体情况修改。
我这里选择了第二种方法来解决问题，修改了数据表结构的字段类型以后，radacct表中就出现了本来就该出现的用户记账信息，问题终于得到了解决。
下面来说一下两种解决方法哪种更好一点，NAS-Port-Id属性目前被各大运营商用作端口绑定的用途，各家运营商都有各自的格式规范，比如中国电信的格式：“{atm|eth|trunk} NAS_slot/NAS_subslot/NAS_port:XPI.XCI AccessNodeIdentifier/ANI_rack/ANI_frame/ANI_slot/ANI_subslot/ANI_port[:ANI_XPI.ANI_XCI]”，实际生产环境下就形成了类似这样的字符串：“eth 4/0/3:4096.1298 SX_WenHuaLu_MA5300/0/0/3/0/18:0.35”，长度很长，运营商会根据这个属性所端口绑定，所以说运行商是不可能在BRAS设备端去限制NAS-Port-Id属性的长度的，另外BRAS设备厂商预置的一些格式长度也都比较长。所以我推荐的还是修改数据库数据表结构字段类型的长度来解决这个问题。修改这个字段类型的长度对于freeradius本身应该也没什么影响，freeradius本身没有那么多类似端口绑定这样的功能，这个字段仅仅是吧信息记录下来而已，应该是一个安全的解决办法。