Очень похоже на то, что mpd запрашивает авторизацию несколько раз:
radius_main.log:
Notice: Nov 13 03:30:51 AuthServer: Login OK <adeep2> from NAS <127.0.0.1> CLID <>
Warn : Nov 13 03:30:51 AuthServer: Unable to claim IP: No such file or directory
Notice: Nov 13 03:30:51 AuthServer: Login incorrect <adeep2> from NAS <127.0.0.1> CLID <>
Notice: Nov 13 03:30:51 AuthServer: Authorization failed for user <adeep2>
Warn : Nov 13 03:30:51 AuthServer: Unable to claim IP: No such file or directory
Notice: Nov 13 03:30:51 AuthServer: Login incorrect <adeep2> from NAS <127.0.0.1> CLID <>
Notice: Nov 13 03:30:51 AuthServer: Authorization failed for user <adeep2>
ERROR : Nov 13 03:30:51 AcctServer: Error! (16)
ERROR : Nov 13 03:30:54 AcctServer: Error! (16)
radius_debug.log:
?Debug : Nov 13 03:30:09 RADIUS DBA: NAS found. Data size <0>
?Debug : Nov 13 03:30:09 AcctServer: Acct packet with session ID: 3381389-cl81
?Debug : Nov 13 03:30:09 RADIUS DBA: NAS found. Data size <0>
?Debug : Nov 13 03:30:09 AcctServer: Acct-Stop packet
Warn : Nov 13 03:30:09 RADIUS DBA: Sending bare packet
?Debug : Nov 13 03:30:09 RADIUS Stream[plugin]: finish log id <0>
?Debug : Nov 13 03:30:09 AcctServer: Reply packet dump: RPacket:
Code: 5; ID: 67
?Debug : Nov 13 03:30:09 RadiusSocket: Moving RADIUS packet into send queue
?Debug : Nov 13 03:30:09 AcctServer: Next...
?Debug : Nov 13 03:30:09 RadiusSocket: Waiting for RADIUS raw data
?Debug : Nov 13 03:30:09 RadiusSocket: RADIUS raw data sent
?Debug : Nov 13 03:30:51 RadiusSocket: RADIUS packet successfully received
?Debug : Nov 13 03:30:51 RadiusSocket: RADIUS raw data obtained
?Debug : Nov 13 03:30:51 RADIUS Packet: Size <149>; HDR.Size <149>
?Debug : Nov 13 03:30:51 AuthServer: Recv...
?Debug : Nov 13 03:30:51 AuthServer: Packet from NAS <127.0.0.1>
?Debug : Nov 13 03:30:51 RADIUS DBA: NAS found. Data size <0>
?Debug : Nov 13 03:30:51 AuthServer: Packet from <127.0.0.1> packet dump: RPacke
Code: 1; ID: 115
<Vendor: 0; Attr: 1>[6]: 616465657032
<Vendor: 0; Attr: 3>[17]: 015f3885bfd01809f2edd8b071cf972e44
<Vendor: 0; Attr: 4>[4]: 7f000001
<Vendor: 0; Attr: 5>[4]: 0000004f
<Vendor: 0; Attr: 6>[4]: 00000002
<Vendor: 0; Attr: 7>[4]: 00000001
<Vendor: 0; Attr: 31>[12]: 303031316438396238383439
<Vendor: 0; Attr: 32>[16]: 636869702e6c6578692e6e65742e7561
<Vendor: 0; Attr: 60>[38]: bb1e686bc8b77437d4964ef877e966f6483c0245abb3f7a799889
<Vendor: 0; Attr: 61>[4]: 00000005
?Debug : Nov 13 03:30:51 AuthServer: User <adeep2> connecting
?Debug : Nov 13 03:30:51 AuthServer: Session for sessionid <adeep2> not found in
?Debug : Nov 13 03:30:51 RADIUS DBA: Info for login <adeep2> found. type <1>
?Debug : Nov 13 03:30:51 AuthServer: Auth scheme: CHAP
?Debug : Nov 13 03:30:51 AuthServer: CHAP: Challenge size: 38
?Debug : Nov 13 03:30:51 AuthServer: CHAP: Authorized user <adeep2>
?Debug : Nov 13 03:30:51 AuthServer: IP claimed: 0xc2091bf2 (<194.9.27.242>)
?Debug : Nov 13 03:30:51 AuthServer: Calling fill radius attributes for service.
?Debug : Nov 13 03:30:51 AuthServer: Calling fill radius attributes for slink. A
?Debug : Nov 13 03:30:51 AuthServer: Calling fill radius attributes for NAS. Att
Notice: Nov 13 03:30:51 AuthServer: Login OK <adeep2> from NAS <127.0.0.1> CLID
?Debug : Nov 13 03:30:51 AuthServer: Setting interim update interval from config
?Debug : Nov 13 03:30:51 AuthServer: Auth reply: RPacket:
Code: 2; ID: 115
<Vendor: 0; Attr: 6>[4]: 00000002
<Vendor: 0; Attr: 7>[4]: 00000001
<Vendor: 0; Attr: 8>[4]: c2091bf2
<Vendor: 0; Attr: 9>[4]: ffffffff
<Vendor: 0; Attr: 10>[4]: 00000000
<Vendor: 0; Attr: 27>[4]: 00015180
<Vendor: 0; Attr: 85>[4]: 0000003c
?Debug : Nov 13 03:30:51 RADIUS Packet: raw data constructed! size <62>
?Debug : Nov 13 03:30:51 RadiusSocket: Moving RADIUS packet into send queue
?Debug : Nov 13 03:30:51 AuthServer: Next...
?Trace : Nov 13 03:30:51 AuthServer: Process loop step
?Debug : Nov 13 03:30:51 RadiusSocket: Waiting for RADIUS raw data
?Debug : Nov 13 03:30:51 RadiusSocket: RADIUS raw data sent
?Debug : Nov 13 03:30:51 RadiusSocket: RADIUS packet successfully received
?Debug : Nov 13 03:30:51 RadiusSocket: RADIUS raw data obtained
?Debug : Nov 13 03:30:51 RADIUS Packet: Size <149>; HDR.Size <149>
?Debug : Nov 13 03:30:51 AuthServer: Recv...
?Debug : Nov 13 03:30:51 AuthServer: Packet from NAS <127.0.0.1>
?Debug : Nov 13 03:30:51 RADIUS DBA: NAS found. Data size <0>
?Debug : Nov 13 03:30:51 AuthServer: Packet from <127.0.0.1> packet dump: RPacke
Code: 1; ID: 115
<Vendor: 0; Attr: 1>[6]: 616465657032
<Vendor: 0; Attr: 3>[17]: 015f3885bfd01809f2edd8b071cf972e44
<Vendor: 0; Attr: 4>[4]: 7f000001
<Vendor: 0; Attr: 5>[4]: 0000004f
<Vendor: 0; Attr: 6>[4]: 00000002
<Vendor: 0; Attr: 7>[4]: 00000001
<Vendor: 0; Attr: 31>[12]: 303031316438396238383439
<Vendor: 0; Attr: 32>[16]: 636869702e6c6578692e6e65742e7561
<Vendor: 0; Attr: 60>[38]: bb1e686bc8b77437d4964ef877e966f6483c0245abb3f7a799889
<Vendor: 0; Attr: 61>[4]: 00000005
?Debug : Nov 13 03:30:51 AuthServer: User <adeep2> connecting
?Debug : Nov 13 03:30:51 AuthServer: Session for sessionid <adeep2> not found in
?Debug : Nov 13 03:30:51 RADIUS DBA: Info for login <adeep2> found. type <1>
?Debug : Nov 13 03:30:51 AuthServer: Auth scheme: CHAP
?Debug : Nov 13 03:30:51 AuthServer: CHAP: Challenge size: 38
?Debug : Nov 13 03:30:51 AuthServer: CHAP: Authorized user <adeep2>
Warn : Nov 13 03:30:51 AuthServer: Unable to claim IP: No such file or directo
?Debug : Nov 13 03:30:51 AuthServer: Calling fill radius attributes for NAS. Att
Notice: Nov 13 03:30:51 AuthServer: Login incorrect <adeep2> from NAS <127.0.0.
Notice: Nov 13 03:30:51 AuthServer: Authorization failed for user <adeep2>
?Debug : Nov 13 03:30:51 AuthServer: Auth reply: RPacket:
Code: 3; ID: 115
Как с этим бороться?
Появилось после обновления версии utm с 5.1.0-17