Re: FreeRADIUS + Postgresql dies unexpectedly
Hi Alan, Thanks for the advice, I've tried the same test with radiusd -f and here are the results Some runs just produce this: # radiusd -f Segmentation fault Others produce a more verbose output, hope it helps: # radiusd -f *** glibc detected *** radiusd: double free or corruption (fasttop): 0x09143220 *** ======= Backtrace: ========= /lib/libc.so.6[0x3c50f1] /lib/libc.so.6(cfree+0x90)[0x3c8bc0] /lib/libcrypto.so.6(CRYPTO_free+0x3a)[0x2a7a5a] /lib/libcrypto.so.6(X509_VERIFY_PARAM_free+0x29)[0x26c029] /lib/libssl.so.6(SSL_free+0x64)[0x13b8b4] /usr/lib/libpq.so.4[0xfdc4e9] /usr/lib/libpq.so.4(pqReadData+0x1da)[0xfd46ba] /usr/lib/libpq.so.4(PQgetResult+0xa0)[0xfd3180] /usr/lib/libpq.so.4[0xfd3348] /usr/lib/libpq.so.4(PQexec+0x27)[0xfd35e7] /usr/lib/freeradius/rlm_sql_postgresql.so[0x18e7bf] /usr/lib/freeradius/rlm_sql.so(rlm_sql_query+0x52)[0xa6b2e2] /usr/lib/freeradius/rlm_sql.so[0xa68a96] radiusd(modcall+0x94e)[0x8062dfe] radiusd(indexed_modcall+0xa5)[0x805fa65] radiusd(module_accounting+0x2c)[0x805fd4c] radiusd(rad_accounting+0xab)[0x804df9b] radiusd(radius_handle_request+0x65)[0x806e4d5] radiusd[0x8066065] /lib/libpthread.so.0[0xd1949b] /lib/libc.so.6(clone+0x5e)[0x42d42e] ======= Memory map: ======== 00110000-00153000 r-xp 00000000 08:02 6291673 /lib/libssl.so.0.9.8e 00153000-00157000 rwxp 00042000 08:02 6291673 /lib/libssl.so.0.9.8e 00157000-00183000 r-xp 00000000 08:02 8986736 /usr/lib/libgssapi_krb5.so.2.2 00183000-00184000 rwxp 0002c000 08:02 8986736 /usr/lib/libgssapi_krb5.so.2.2 00184000-00186000 r-xp 00000000 08:02 6291658 /lib/libcom_err.so.2.1 00186000-00187000 rwxp 00001000 08:02 6291658 /lib/libcom_err.so.2.1 00187000-00189000 r-xp 00000000 08:02 6291546 /lib/libkeyutils-1.2.so 00189000-0018a000 rwxp 00001000 08:02 6291546 /lib/libkeyutils-1.2.so 0018a000-0018c000 r-xp 00000000 08:02 9085015 /usr/lib/freeradius/rlm_acct_unique-2.1.7.so 0018c000-0018d000 rwxp 00001000 08:02 9085015 /usr/lib/freeradius/rlm_acct_unique-2.1.7.so 0018d000-00191000 r-xp 00000000 08:02 9085105 /usr/lib/freeradius/rlm_sql_postgresql-2.1.7.so 00191000-00192000 rwxp 00004000 08:02 9085105 /usr/lib/freeradius/rlm_sql_postgresql-2.1.7.so 00194000-0019d000 r-xp 00000000 08:02 6291484 /lib/libcrypt-2.5.so 0019d000-0019e000 r-xp 00008000 08:02 6291484 /lib/libcrypt-2.5.so 0019e000-0019f000 rwxp 00009000 08:02 6291484 /lib/libcrypt-2.5.so 0019f000-001c6000 rwxp 0019f000 00:00 0 001d4000-001d5000 r-xp 001d4000 00:00 0 [vdso] 001d5000-002ff000 r-xp 00000000 08:02 6291671 /lib/libcrypto.so.0.9.8e 002ff000-00312000 rwxp 00129000 08:02 6291671 /lib/libcrypto.so.0.9.8e 00312000-00316000 rwxp 00312000 00:00 0 00316000-00328000 r-xp 00000000 08:02 8984623 /usr/lib/libz.so.1.2.3 00328000-00329000 rwxp 00011000 08:02 8984623 /usr/lib/libz.so.1.2.3 00345000-00358000 r-xp 00000000 08:02 6291490 /lib/libnsl-2.5.so 00358000-00359000 r-xp 00012000 08:02 6291490 /lib/libnsl-2.5.so 00359000-0035a000 rwxp 00013000 08:02 6291490 /lib/libnsl-2.5.so 0035a000-0035c000 rwxp 0035a000 00:00 0 0035c000-0049a000 r-xp 00000000 08:02 6291480 /lib/libc-2.5.so 0049a000-0049c000 r-xp 0013e000 08:02 6291480 /lib/libc-2.5.so 0049c000-0049d000 rwxp 00140000 08:02 6291480 /lib/libc-2.5.so 0049d000-004a0000 rwxp 0049d000 00:00 0 004a0000-00533000 r-xp 00000000 08:02 8986750 /usr/lib/libkrb5.so.3.3 00533000-00536000 rwxp 00092000 08:02 8986750 /usr/lib/libkrb5.so.3.3 00640000-0065a000 r-xp 00000000 08:02 6291473 /lib/ld-2.5.so 0065a000-0065b000 r-xp 00019000 08:02 6291473 /lib/ld-2.5.so 0065b000-0065c000 rwxp 0001a000 08:02 6291473 /lib/ld-2.5.so 006b9000-006c8000 r-xp 00000000 08:02 6291506 /lib/libresolv-2.5.so 006c8000-006c9000 r-xp 0000e000 08:02 6291506 /lib/libresolv-2.5.so 006c9000-006ca000 rwxp 0000f000 08:02 6291506 /lib/libresolv-2.5.so 006ca000-006cc000 rwxp 006ca000 00:00 0 006f4000-006f6000 r-xp 00000000 08:02 9085067 /usr/lib/freeradius/rlm_files-2.1.7.so 006f6000-006f7000 rwxp 00001000 08:02 9085067 /usr/lib/freeradius/rlm_files-2.1.7.so 00753000-00769000 r-xp 00000000 08:02 6291646 /lib/libselinux.so.1 00769000-0076b000 rwxp 00015000 08:02 6291646 /lib/libselinux.so.1 00787000-00792000 r-xp 00000000 08:02 6291458 Aborted # radiusd -f *** glibc detected *** radiusd: double free or corruption (fasttop): 0x0993eeb0 *** ======= Backtrace: ========= /lib/libc.so.6[0x1790f1] /lib/libc.so.6(cfree+0x90)[0x17cbc0] /lib/libcrypto.so.6(CRYPTO_free+0x3a)[0x483a5a] /lib/libcrypto.so.6(X509_VERIFY_PARAM_free+0x29)[0x448029] /lib/libssl.so.6(SSL_free+0x64)[0xede8b4] /usr/lib/libpq.so.4[0x3a14e9] /usr/lib/libpq.so.4(pqReadData+0x1da)[0x3996ba] /usr/lib/libpq.so.4(PQgetResult+0xa0)[0x398180] /usr/lib/libpq.so.4[0x39828c] /usr/lib/freeradius/rlm_sql_postgresql.so[0x3887bf] /usr/lib/freeradius/rlm_sql.so(rlm_sql_query+0x52)[0x9e82e2] /usr/lib/freeradius/rlm_sql.so[0x9e5c3b] radiusd(modcall+0x94e)[0x8062dfe] radiusd(indexed_modcall+0xa5)[0x805fa65] radiusd(module_accounting+0x2c)[0x805fd4c] radiusd(rad_accounting+0xab)[0x804df9b] radiusd(radius_handle_request+0x65)[0x806e4d5] radiusd[0x8066065] /lib/libpthread.so.0[0xdc449b] /lib/libc.so.6(clone+0x5e)[0x1e142e] ======= Memory map: ======== 00110000-0024e000 r-xp 00000000 08:02 6291480 /lib/libc-2.5.so 0024e000-00250000 r-xp 0013e000 08:02 6291480 /lib/libc-2.5.so 00250000-00251000 rwxp 00140000 08:02 6291480 /lib/libc-2.5.so 00251000-00254000 rwxp 00251000 00:00 0 00254000-00279000 r-xp 00000000 08:02 8986740 /usr/lib/libk5crypto.so.3.1 00279000-0027a000 rwxp 00025000 08:02 8986740 /usr/lib/libk5crypto.so.3.1 0027a000-00290000 r-xp 00000000 08:02 6291646 /lib/libselinux.so.1 00290000-00292000 rwxp 00015000 08:02 6291646 /lib/libselinux.so.1 00292000-00294000 r-xp 00000000 08:02 9085067 /usr/lib/freeradius/rlm_files-2.1.7.so 00294000-00295000 rwxp 00001000 08:02 9085067 /usr/lib/freeradius/rlm_files-2.1.7.so 00298000-002a7000 r-xp 00000000 08:02 6291506 /lib/libresolv-2.5.so 002a7000-002a8000 r-xp 0000e000 08:02 6291506 /lib/libresolv-2.5.so 002a8000-002a9000 rwxp 0000f000 08:02 6291506 /lib/libresolv-2.5.so 002a9000-002ab000 rwxp 002a9000 00:00 0 002ab000-0033e000 r-xp 00000000 08:02 8986750 /usr/lib/libkrb5.so.3.3 0033e000-00341000 rwxp 00092000 08:02 8986750 /usr/lib/libkrb5.so.3.3 00341000-0037c000 r-xp 00000000 08:02 6291555 /lib/libsepol.so.1 0037c000-0037d000 rwxp 0003a000 08:02 6291555 /lib/libsepol.so.1 0037d000-00387000 rwxp 0037d000 00:00 0 00387000-0038b000 r-xp 00000000 08:02 9085105 /usr/lib/freeradius/rlm_sql_postgresql-2.1.7.so 0038b000-0038c000 rwxp 00004000 08:02 9085105 /usr/lib/freeradius/rlm_sql_postgresql-2.1.7.so 0038c000-003ab000 r-xp 00000000 08:02 8986821 /usr/lib/libpq.so.4.1 003ab000-003ac000 rwxp 0001f000 08:02 8986821 /usr/lib/libpq.so.4.1 003b1000-004db000 r-xp 00000000 08:02 6291671 /lib/libcrypto.so.0.9.8e 004db000-004ee000 rwxp 00129000 08:02 6291671 /lib/libcrypto.so.0.9.8e 004ee000-004f2000 rwxp 004ee000 00:00 0 004f2000-004fd000 r-xp 00000000 08:02 6291458 /lib/libgcc_s-4.1.2-20080825.so.1 004fd000-004fe000 rwxp 0000a000 08:02 6291458 /lib/libgcc_s-4.1.2-20080825.so.1 0050a000-00510000 r-xp 00000000 08:02 8985722 /usr/lib/libltdl.so.3.1.4 00510000-00511000 rwxp 00005000 08:02 8985722 /usr/lib/libltdl.so.3.1.4 00527000-00539000 r-xp 00000000 08:02 8984623 /usr/lib/libz.so.1.2.3 00539000-0053a000 rwxp 00011000 08:02 8984623 /usr/lib/libz.so.1.2.3 005bd000-005c5000 r-xp 00000000 08:02 8986752 /usr/lib/libkrb5support.so.0.1 005c5000-005c6000 rwxp 00007000 08:02 8986752 /usr/lib/libkrb5support.so.0.1 00769000-00772000 r-xp 00000000 08:02 6291484 /lib/libcrypt-2.5.so 00772000-00773000 r-xp 00008000 08:02 6291484 /lib/libcrypt-2.5.so 00773000-00774000 rwxp 00009000 08:02 6291484 /lib/libcrypt-2.5.so 00774000-0079b000 rwxp 00774000 00:00 0 0081d000-0081f000 r-xp 00000000 08:02 9085095 /usr/lib/freeradius/rlm_sql_log-2.1.7.so 0081f000-00820000 rwxp 00001000 08:02 9085095 /usr/lib/freeradius/rlm_sql_log-2.1.7.so 0083c000-0083d000 r-xp 0083c000 00:00 0 [vdso] 00868000-00894000 r-xp 00000000 08:02 8986736 /usr/lib/libgssapi_krb5.so.2.2 00894000-00895000 rwxp 0002c000 08:02 8986736 /usr/lib/libgssapi_krb5.so.2.2 009c2000-009d5000 r-xp 00000000 08:02 6291490 /lib/libnsl-2.5.so 009d5000-009d6000 r-xp 00012000 08:02 6291490 /lib/libnsl-2.5.so 009d6000-009d7000 rwxp 00013000 08:02 6291490 /lib/libnsl-2.5.so 009d7000-009d9000 rwxp 009d7000 00:00 0 009e3000-009eb000 r-xp 00000000 08:02 9085093 /usr/lib/freeradius/rlm_sql-2.1.7.so 009eb000-009ec000 rwxp 00007000 08:02 9085093 /usr/lib/freeradius/rlm_sql-2.1.7.so 00b28000-00b2a000 r-xp 00000000 08:02 6291546 /lib/libkeyutils-1.2.so 00b2a000-00b2b000 rwxp 00001000 08:02 6291546 /lib/libkeyutils-1.2.so 00c42000-00c44000 r-xp 00000000 08:02 9085059 /usr/lib/freeradius/rlm_exec-2.1.7.so 00c44000-00c45000 rwxp 00001000 08:02 9085059 /usr/lib/freeradius/rlm_exec-2.1.7.so 00c89000-00c8b000 r-xp 00000000 08:02 6291486 /lib/libdl-2.5.so 00c8b000-00c8c000 r-xp 00001000 08:02 6291486 /lib/libdl-2.5.so 00c8c000-00c8d000 rwxp 00002000 08:02 6291486 /lib/libdl-2.5.so 00caf000-00cc9000 r-xp 00000000 08:02 6291473 /lib/ld-2.5.so 00cc9000-00cca000 r-xp 00019000 08:02 6291473 /lib/ld-2.5.so 00cca000-00ccb000 rwxp 0001a000 08:02 6291473 /lib/ld-2.5.so 00cfd000-00cff000 r-xp 00000000 08:02 9085015 /usr/lib/freeradius/rlm_acct_unique-2.1.7.so 00cff000-00d00000 rwxp 00001000 08:02 9085015 /usr/lib/freeradius/rlm_acct_unique-2.1.7.so 00d5a000-00d63000 r-xp 00000000 08:02 6291496 /lib/libnss_files-2.5.so 00d63000-00d64000 r-xp 00008000 08:02 6291496 /lib/libnss_files-2.5.so 00d64000-00d65000 rwxp 00009000 08:02 6291496 /lib/libnss_files-2.5.so 00dbf000-00dd2000 r-xp 00000000 08:02 6291504 /lib/libpthread-2.5.so 00dd2000-00dd3000 r-xp 00012000 08:02 6291504 /lib/libpthread-2.5.so 00dd3000-00dd4000 rwxp 00013000 08:02 6291504 /lib/libpthread-2.5.so 00dd4000-00dd6000 rwxp 00dd4000 00:00 0 00e6d000-00e8d000 r-xp 00000000 08:02 9080245 /usr/lib/freeradius/libfreeradius-radius-2.1.7.so 00e8d000-00e8e000 rwxp 00020000 08:02 9080245 /usr/lib/freeradius/libfreeradius-radius-2.1.7.so 00e8e000-00e8f000 rwxp 00e8e000 00:00 0 00eb3000-00ef6000 r-xp 00000000 08:02 6291673 /lib/libssl.so.0.9.8e 00ef6000-00efa000 rwxp 00042000 08:02 6291673 /lib/libssl.so.0.9.8e 00f94000-00f96000 r-xp 00000000 08:02 6291658 /lib/libcom_err.so.2.1 00f96000-00f97000 rwxp 00001000 08:02 6291658 /lib/libcom_err.so.2.1 08048000-08085000 r-xp 00000000 08:02 8988421 /usr/sbin/radiusd 08085000-08087000 rw-p 0003d000 08:02 8988421 /usr/sbin/radiusd 08087000-08088000 rw-p 08087000 00:00 0 0978e000-0a07d000 rw-p 0978e000 00:00 0 [heap] b19fb000-b19fc000 ---p b19fb000 00:00 0 b19fc000-b23fc000 rw-p b19fc000 00:00 0 b23fc000-b23fd000 ---p b23fc000 00:00 0 b23fd000-b2dfd000 rw-p b23fd000 00:00 0 b2dfd000-b2dfe000 ---p b2dfd000 00:00 0 b2dfe000-b37fe000 rw-p b2dfe000 00:00 0 b37fe000-b37ff000 ---p b37fe000 00:00 0 b37ff000-b41ff000 rw-p b37ff000 00:00 0 b41ff000-b4200000 ---p b41ff000 00:00 0 b4200000-b4c22000 rw-p b4200000 00:00 0 b4c22000-b4d00000 ---p b4c22000 00:00 0 b4dd9000-b4dda000 ---p b4dd9000 00:00 0 b4dda000-b57da000 rw-p b4dda000 00:00 0 b57da000-b57db000 ---p b57da000 00:00 0 b57db000-b61db000 rw-p b57db000 00:00 0 b61db000-b61dc000 ---p b61db000 00:00 0 b61dc000-b6bdc000 rw-p b61dc000 00:00 0 b6bdc000-b6bdd000 ---p b6bdc000 00:00 0 b6bdd000-b75dd000 rw-p b6bdd000 00:00 0 b75dd000-b75de000 ---p b75dd000 00:00 0 b75de000-b7fe3000 rw-p b75de000 00:00 0 b7fe7000-b7fe8000 rw-p b7fe7000 00:00 0 bf842000-bf858000 rw-p bffe9000 00:00 0 [stack] Aborted Also in my postgresql log i see the following when radiusd dies <2009-10-23 11:01:40.167 BST> LOG: SSL error: wrong version number <2009-10-23 11:01:40.167 BST> LOG: could not receive data from client: Connection reset by peer <2009-10-23 11:01:40.167 BST> LOG: unexpected EOF on client connection <2009-10-23 11:01:40.169 BST> LOG: could not receive data from client: Connection reset by peer <2009-10-23 11:01:40.169 BST> LOG: could not receive data from client: Connection reset by peer <2009-10-23 11:01:40.169 BST> LOG: unexpected EOF on client connection <2009-10-23 11:01:40.169 BST> LOG: unexpected EOF on client connection <2009-10-23 11:01:40.170 BST> LOG: could not receive data from client: Connection reset by peer <2009-10-23 11:01:40.170 BST> LOG: could not receive data from client: Connection reset by peer <2009-10-23 11:01:40.170 BST> LOG: unexpected EOF on client connection <2009-10-23 11:01:40.170 BST> LOG: unexpected EOF on client connection <2009-10-23 11:01:40.175 BST> LOG: could not receive data from client: Connection reset by peer <2009-10-23 11:01:40.175 BST> LOG: unexpected EOF on client connection <2009-10-23 11:01:40.175 BST> LOG: could not receive data from client: Connection reset by peer <2009-10-23 11:01:40.175 BST> LOG: unexpected EOF on client connection <2009-10-23 11:01:40.176 BST> LOG: could not receive data from client: Connection reset by peer <2009-10-23 11:01:40.176 BST> LOG: unexpected EOF on client connection <2009-10-23 11:01:40.176 BST> LOG: could not receive data from client: Connection reset by peer <2009-10-23 11:01:40.176 BST> LOG: unexpected EOF on client connection <2009-10-23 11:01:40.175 BST> LOG: could not receive data from client: Connection reset by peer <2009-10-23 11:01:40.177 BST> LOG: unexpected EOF on client connection <2009-10-23 11:01:40.177 BST> LOG: could not receive data from client: Connection reset by peer <2009-10-23 11:01:40.177 BST> LOG: unexpected EOF on client connection <2009-10-23 11:01:40.178 BST> LOG: could not receive data from client: Connection reset by peer <2009-10-23 11:01:40.178 BST> LOG: unexpected EOF on client connection The message regarding SSL seems to alternate between the follwoing: LOG: SSL error: wrong version number LOG: could not accept SSL connection: EOF detected LOG: SSL error: decryption failed or bad record mac LOG: SSL error: block cipher pad is wrong In my radius.log i've noticed a couple of times there are some postgresql errors Fri Oct 23 11:18:08 2009 : Info: rlm_sql (sql): Driver rlm_sql_postgresql (module rlm_sql_postgresql) loaded and linked Fri Oct 23 11:18:08 2009 : Info: rlm_sql (sql): Attempting to connect to postgres@localhost:/gapdb Fri Oct 23 11:18:08 2009 : Info: Loaded virtual server <default> Fri Oct 23 11:18:08 2009 : Info: Ready to process requests. Fri Oct 23 11:18:16 2009 : Error: [sql] stop packet with zero session length. [user 'JoePublic7', nas '172.20.200.226'] Fri Oct 23 11:18:16 2009 : Error: [sql] stop packet with zero session length. [user 'admin', nas '172.20.200.226'] Fri Oct 23 11:18:16 2009 : Error: [sql] stop packet with zero session length. [user 'admin', nas '172.20.200.226'] Fri Oct 23 11:18:16 2009 : Error: [sql] stop packet with zero session length. [user 'admin', nas '172.20.200.226'] Fri Oct 23 11:18:16 2009 : Error: [sql] stop packet with zero session length. [user 'admin', nas '172.20.200.226'] Fri Oct 23 11:18:16 2009 : Error: [sql] stop packet with zero session length. [user 'admin', nas '172.20.200.226'] Fri Oct 23 11:18:16 2009 : Error: rlm_sql_postgresql: PostgreSQL Query failed Error: Fri Oct 23 11:18:16 2009 : Error: rlm_sql_postgresql: Socket not connected Fri Oct 23 11:18:16 2009 : Error: [sql] stop packet with zero session length. [user 'admin', nas '172.20.200.226'] Fri Oct 23 11:18:16 2009 : Error: [sql] stop packet with zero session length. [user 'admin', nas '172.20.200.226'] Fri Oct 23 11:18:16 2009 : Error: [sql] stop packet with zero session length. [user 'admin', nas '172.20.200.226'] Fri Oct 23 11:19:02 2009 : Info: rlm_sql (sql): Driver rlm_sql_postgresql (module rlm_sql_postgresql) loaded and linked Fri Oct 23 11:19:02 2009 : Info: rlm_sql (sql): Attempting to connect to postgres@localhost:/gapdb Fri Oct 23 11:19:02 2009 : Info: Loaded virtual server <default> Fri Oct 23 11:19:02 2009 : Info: Ready to process requests. Fri Oct 23 11:19:05 2009 : Error: [sql] stop packet with zero session length. [user 'JoePublic7', nas '172.20.200.226'] Fri Oct 23 11:19:05 2009 : Error: [sql] stop packet with zero session length. [user 'admin', nas '172.20.200.226'] Fri Oct 23 11:19:05 2009 : Error: [sql] stop packet with zero session length. [user 'admin', nas '172.20.200.226'] Fri Oct 23 11:19:05 2009 : Error: [sql] stop packet with zero session length. [user 'admin', nas '172.20.200.226'] Fri Oct 23 11:19:05 2009 : Error: [sql] stop packet with zero session length. [user 'admin', nas '172.20.200.226'] Fri Oct 23 11:19:05 2009 : Error: [sql] stop packet with zero session length. [user 'admin', nas '172.20.200.226'] Fri Oct 23 11:19:05 2009 : Error: [sql] stop packet with zero session length. [user 'admin', nas '172.20.200.226'] Fri Oct 23 11:19:05 2009 : Error: [sql] stop packet with zero session length. [user 'admin', nas '172.20.200.226'] Fri Oct 23 11:19:05 2009 : Error: [sql] stop packet with zero session length. [user 'admin', nas '172.20.200.226'] Fri Oct 23 11:19:05 2009 : Error: [sql] stop packet with zero session length. [user '001f3b887d19', nas '172.20.200.226'] Fri Oct 23 11:19:05 2009 : Error: [sql] stop packet with zero session length. [user '001f3b887d19', nas '172.20.200.226'] Fri Oct 23 11:19:05 2009 : Error: [sql] stop packet with zero session length. [user 'admin', nas '172.20.200.226'] Fri Oct 23 11:19:05 2009 : Error: [sql] stop packet with zero session length. [user 'admin', nas '172.20.200.226'] Fri Oct 23 11:19:05 2009 : Error: [sql] stop packet with zero session length. [user 'admin', nas '172.20.200.226'] Fri Oct 23 11:19:05 2009 : Error: [sql] stop packet with zero session length. [user 'admin', nas '172.20.200.226'] Fri Oct 23 11:19:05 2009 : Error: rlm_sql_postgresql: PostgreSQL Query failed Error: SSL SYSCALL error: Resource temporarily unavailable I've also setup a sql_log module to capture the sql queries being performed and later ran that sql succesfully with the command: # psql -h 127.0.0.1 -U postgres gapdb < /var/log/radius/radacct/sql-relay Again thank you for the help, hope this helps. Cheers, Duarte On 22/10/2009 18:17, "Alan DeKok" <aland@deployingradius.com> wrote:
Duarte Fonseca wrote:
I've got a freeRadius (v2.1.7) install running on CentOs using postgresql to store accounting data and have noticed that occasionally freeRadius seems to die unexpectedly.
See doc/bugs. You can run the server in foreground mode (radiusd -f), too.
If it dies after a few packets, the problem should be pretty simple to find && fix.
Alan DeKok. - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
Hi list, Just checking if anyone has any more suggestions on how I should proceed with this. Would greatly appreciate it if someone pointed me in the right direction. Thank you, Duarte 2009/10/23 Duarte Fonseca <fonseca.duarte@gmail.com>:
Hi Alan,
Thanks for the advice, I've tried the same test with radiusd -f and here are the results
Some runs just produce this:
# radiusd -f Segmentation fault
Others produce a more verbose output, hope it helps:
# radiusd -f *** glibc detected *** radiusd: double free or corruption (fasttop): 0x09143220 *** ======= Backtrace: ========= /lib/libc.so.6[0x3c50f1] /lib/libc.so.6(cfree+0x90)[0x3c8bc0] /lib/libcrypto.so.6(CRYPTO_free+0x3a)[0x2a7a5a] /lib/libcrypto.so.6(X509_VERIFY_PARAM_free+0x29)[0x26c029] /lib/libssl.so.6(SSL_free+0x64)[0x13b8b4] /usr/lib/libpq.so.4[0xfdc4e9] /usr/lib/libpq.so.4(pqReadData+0x1da)[0xfd46ba] /usr/lib/libpq.so.4(PQgetResult+0xa0)[0xfd3180] /usr/lib/libpq.so.4[0xfd3348] /usr/lib/libpq.so.4(PQexec+0x27)[0xfd35e7] /usr/lib/freeradius/rlm_sql_postgresql.so[0x18e7bf] /usr/lib/freeradius/rlm_sql.so(rlm_sql_query+0x52)[0xa6b2e2] /usr/lib/freeradius/rlm_sql.so[0xa68a96] radiusd(modcall+0x94e)[0x8062dfe] radiusd(indexed_modcall+0xa5)[0x805fa65] radiusd(module_accounting+0x2c)[0x805fd4c] radiusd(rad_accounting+0xab)[0x804df9b] radiusd(radius_handle_request+0x65)[0x806e4d5] radiusd[0x8066065] /lib/libpthread.so.0[0xd1949b] /lib/libc.so.6(clone+0x5e)[0x42d42e] ======= Memory map: ======== 00110000-00153000 r-xp 00000000 08:02 6291673 /lib/libssl.so.0.9.8e 00153000-00157000 rwxp 00042000 08:02 6291673 /lib/libssl.so.0.9.8e 00157000-00183000 r-xp 00000000 08:02 8986736 /usr/lib/libgssapi_krb5.so.2.2 00183000-00184000 rwxp 0002c000 08:02 8986736 /usr/lib/libgssapi_krb5.so.2.2 00184000-00186000 r-xp 00000000 08:02 6291658 /lib/libcom_err.so.2.1 00186000-00187000 rwxp 00001000 08:02 6291658 /lib/libcom_err.so.2.1 00187000-00189000 r-xp 00000000 08:02 6291546 /lib/libkeyutils-1.2.so 00189000-0018a000 rwxp 00001000 08:02 6291546 /lib/libkeyutils-1.2.so 0018a000-0018c000 r-xp 00000000 08:02 9085015 /usr/lib/freeradius/rlm_acct_unique-2.1.7.so 0018c000-0018d000 rwxp 00001000 08:02 9085015 /usr/lib/freeradius/rlm_acct_unique-2.1.7.so 0018d000-00191000 r-xp 00000000 08:02 9085105 /usr/lib/freeradius/rlm_sql_postgresql-2.1.7.so 00191000-00192000 rwxp 00004000 08:02 9085105 /usr/lib/freeradius/rlm_sql_postgresql-2.1.7.so 00194000-0019d000 r-xp 00000000 08:02 6291484 /lib/libcrypt-2.5.so 0019d000-0019e000 r-xp 00008000 08:02 6291484 /lib/libcrypt-2.5.so 0019e000-0019f000 rwxp 00009000 08:02 6291484 /lib/libcrypt-2.5.so 0019f000-001c6000 rwxp 0019f000 00:00 0 001d4000-001d5000 r-xp 001d4000 00:00 0 [vdso] 001d5000-002ff000 r-xp 00000000 08:02 6291671 /lib/libcrypto.so.0.9.8e 002ff000-00312000 rwxp 00129000 08:02 6291671 /lib/libcrypto.so.0.9.8e 00312000-00316000 rwxp 00312000 00:00 0 00316000-00328000 r-xp 00000000 08:02 8984623 /usr/lib/libz.so.1.2.3 00328000-00329000 rwxp 00011000 08:02 8984623 /usr/lib/libz.so.1.2.3 00345000-00358000 r-xp 00000000 08:02 6291490 /lib/libnsl-2.5.so 00358000-00359000 r-xp 00012000 08:02 6291490 /lib/libnsl-2.5.so 00359000-0035a000 rwxp 00013000 08:02 6291490 /lib/libnsl-2.5.so 0035a000-0035c000 rwxp 0035a000 00:00 0 0035c000-0049a000 r-xp 00000000 08:02 6291480 /lib/libc-2.5.so 0049a000-0049c000 r-xp 0013e000 08:02 6291480 /lib/libc-2.5.so 0049c000-0049d000 rwxp 00140000 08:02 6291480 /lib/libc-2.5.so 0049d000-004a0000 rwxp 0049d000 00:00 0 004a0000-00533000 r-xp 00000000 08:02 8986750 /usr/lib/libkrb5.so.3.3 00533000-00536000 rwxp 00092000 08:02 8986750 /usr/lib/libkrb5.so.3.3 00640000-0065a000 r-xp 00000000 08:02 6291473 /lib/ld-2.5.so 0065a000-0065b000 r-xp 00019000 08:02 6291473 /lib/ld-2.5.so 0065b000-0065c000 rwxp 0001a000 08:02 6291473 /lib/ld-2.5.so 006b9000-006c8000 r-xp 00000000 08:02 6291506 /lib/libresolv-2.5.so 006c8000-006c9000 r-xp 0000e000 08:02 6291506 /lib/libresolv-2.5.so 006c9000-006ca000 rwxp 0000f000 08:02 6291506 /lib/libresolv-2.5.so 006ca000-006cc000 rwxp 006ca000 00:00 0 006f4000-006f6000 r-xp 00000000 08:02 9085067 /usr/lib/freeradius/rlm_files-2.1.7.so 006f6000-006f7000 rwxp 00001000 08:02 9085067 /usr/lib/freeradius/rlm_files-2.1.7.so 00753000-00769000 r-xp 00000000 08:02 6291646 /lib/libselinux.so.1 00769000-0076b000 rwxp 00015000 08:02 6291646 /lib/libselinux.so.1 00787000-00792000 r-xp 00000000 08:02 6291458 Aborted
# radiusd -f *** glibc detected *** radiusd: double free or corruption (fasttop): 0x0993eeb0 *** ======= Backtrace: ========= /lib/libc.so.6[0x1790f1] /lib/libc.so.6(cfree+0x90)[0x17cbc0] /lib/libcrypto.so.6(CRYPTO_free+0x3a)[0x483a5a] /lib/libcrypto.so.6(X509_VERIFY_PARAM_free+0x29)[0x448029] /lib/libssl.so.6(SSL_free+0x64)[0xede8b4] /usr/lib/libpq.so.4[0x3a14e9] /usr/lib/libpq.so.4(pqReadData+0x1da)[0x3996ba] /usr/lib/libpq.so.4(PQgetResult+0xa0)[0x398180] /usr/lib/libpq.so.4[0x39828c] /usr/lib/freeradius/rlm_sql_postgresql.so[0x3887bf] /usr/lib/freeradius/rlm_sql.so(rlm_sql_query+0x52)[0x9e82e2] /usr/lib/freeradius/rlm_sql.so[0x9e5c3b] radiusd(modcall+0x94e)[0x8062dfe] radiusd(indexed_modcall+0xa5)[0x805fa65] radiusd(module_accounting+0x2c)[0x805fd4c] radiusd(rad_accounting+0xab)[0x804df9b] radiusd(radius_handle_request+0x65)[0x806e4d5] radiusd[0x8066065] /lib/libpthread.so.0[0xdc449b] /lib/libc.so.6(clone+0x5e)[0x1e142e] ======= Memory map: ======== 00110000-0024e000 r-xp 00000000 08:02 6291480 /lib/libc-2.5.so 0024e000-00250000 r-xp 0013e000 08:02 6291480 /lib/libc-2.5.so 00250000-00251000 rwxp 00140000 08:02 6291480 /lib/libc-2.5.so 00251000-00254000 rwxp 00251000 00:00 0 00254000-00279000 r-xp 00000000 08:02 8986740 /usr/lib/libk5crypto.so.3.1 00279000-0027a000 rwxp 00025000 08:02 8986740 /usr/lib/libk5crypto.so.3.1 0027a000-00290000 r-xp 00000000 08:02 6291646 /lib/libselinux.so.1 00290000-00292000 rwxp 00015000 08:02 6291646 /lib/libselinux.so.1 00292000-00294000 r-xp 00000000 08:02 9085067 /usr/lib/freeradius/rlm_files-2.1.7.so 00294000-00295000 rwxp 00001000 08:02 9085067 /usr/lib/freeradius/rlm_files-2.1.7.so 00298000-002a7000 r-xp 00000000 08:02 6291506 /lib/libresolv-2.5.so 002a7000-002a8000 r-xp 0000e000 08:02 6291506 /lib/libresolv-2.5.so 002a8000-002a9000 rwxp 0000f000 08:02 6291506 /lib/libresolv-2.5.so 002a9000-002ab000 rwxp 002a9000 00:00 0 002ab000-0033e000 r-xp 00000000 08:02 8986750 /usr/lib/libkrb5.so.3.3 0033e000-00341000 rwxp 00092000 08:02 8986750 /usr/lib/libkrb5.so.3.3 00341000-0037c000 r-xp 00000000 08:02 6291555 /lib/libsepol.so.1 0037c000-0037d000 rwxp 0003a000 08:02 6291555 /lib/libsepol.so.1 0037d000-00387000 rwxp 0037d000 00:00 0 00387000-0038b000 r-xp 00000000 08:02 9085105 /usr/lib/freeradius/rlm_sql_postgresql-2.1.7.so 0038b000-0038c000 rwxp 00004000 08:02 9085105 /usr/lib/freeradius/rlm_sql_postgresql-2.1.7.so 0038c000-003ab000 r-xp 00000000 08:02 8986821 /usr/lib/libpq.so.4.1 003ab000-003ac000 rwxp 0001f000 08:02 8986821 /usr/lib/libpq.so.4.1 003b1000-004db000 r-xp 00000000 08:02 6291671 /lib/libcrypto.so.0.9.8e 004db000-004ee000 rwxp 00129000 08:02 6291671 /lib/libcrypto.so.0.9.8e 004ee000-004f2000 rwxp 004ee000 00:00 0 004f2000-004fd000 r-xp 00000000 08:02 6291458 /lib/libgcc_s-4.1.2-20080825.so.1 004fd000-004fe000 rwxp 0000a000 08:02 6291458 /lib/libgcc_s-4.1.2-20080825.so.1 0050a000-00510000 r-xp 00000000 08:02 8985722 /usr/lib/libltdl.so.3.1.4 00510000-00511000 rwxp 00005000 08:02 8985722 /usr/lib/libltdl.so.3.1.4 00527000-00539000 r-xp 00000000 08:02 8984623 /usr/lib/libz.so.1.2.3 00539000-0053a000 rwxp 00011000 08:02 8984623 /usr/lib/libz.so.1.2.3 005bd000-005c5000 r-xp 00000000 08:02 8986752 /usr/lib/libkrb5support.so.0.1 005c5000-005c6000 rwxp 00007000 08:02 8986752 /usr/lib/libkrb5support.so.0.1 00769000-00772000 r-xp 00000000 08:02 6291484 /lib/libcrypt-2.5.so 00772000-00773000 r-xp 00008000 08:02 6291484 /lib/libcrypt-2.5.so 00773000-00774000 rwxp 00009000 08:02 6291484 /lib/libcrypt-2.5.so 00774000-0079b000 rwxp 00774000 00:00 0 0081d000-0081f000 r-xp 00000000 08:02 9085095 /usr/lib/freeradius/rlm_sql_log-2.1.7.so 0081f000-00820000 rwxp 00001000 08:02 9085095 /usr/lib/freeradius/rlm_sql_log-2.1.7.so 0083c000-0083d000 r-xp 0083c000 00:00 0 [vdso] 00868000-00894000 r-xp 00000000 08:02 8986736 /usr/lib/libgssapi_krb5.so.2.2 00894000-00895000 rwxp 0002c000 08:02 8986736 /usr/lib/libgssapi_krb5.so.2.2 009c2000-009d5000 r-xp 00000000 08:02 6291490 /lib/libnsl-2.5.so 009d5000-009d6000 r-xp 00012000 08:02 6291490 /lib/libnsl-2.5.so 009d6000-009d7000 rwxp 00013000 08:02 6291490 /lib/libnsl-2.5.so 009d7000-009d9000 rwxp 009d7000 00:00 0 009e3000-009eb000 r-xp 00000000 08:02 9085093 /usr/lib/freeradius/rlm_sql-2.1.7.so 009eb000-009ec000 rwxp 00007000 08:02 9085093 /usr/lib/freeradius/rlm_sql-2.1.7.so 00b28000-00b2a000 r-xp 00000000 08:02 6291546 /lib/libkeyutils-1.2.so 00b2a000-00b2b000 rwxp 00001000 08:02 6291546 /lib/libkeyutils-1.2.so 00c42000-00c44000 r-xp 00000000 08:02 9085059 /usr/lib/freeradius/rlm_exec-2.1.7.so 00c44000-00c45000 rwxp 00001000 08:02 9085059 /usr/lib/freeradius/rlm_exec-2.1.7.so 00c89000-00c8b000 r-xp 00000000 08:02 6291486 /lib/libdl-2.5.so 00c8b000-00c8c000 r-xp 00001000 08:02 6291486 /lib/libdl-2.5.so 00c8c000-00c8d000 rwxp 00002000 08:02 6291486 /lib/libdl-2.5.so 00caf000-00cc9000 r-xp 00000000 08:02 6291473 /lib/ld-2.5.so 00cc9000-00cca000 r-xp 00019000 08:02 6291473 /lib/ld-2.5.so 00cca000-00ccb000 rwxp 0001a000 08:02 6291473 /lib/ld-2.5.so 00cfd000-00cff000 r-xp 00000000 08:02 9085015 /usr/lib/freeradius/rlm_acct_unique-2.1.7.so 00cff000-00d00000 rwxp 00001000 08:02 9085015 /usr/lib/freeradius/rlm_acct_unique-2.1.7.so 00d5a000-00d63000 r-xp 00000000 08:02 6291496 /lib/libnss_files-2.5.so 00d63000-00d64000 r-xp 00008000 08:02 6291496 /lib/libnss_files-2.5.so 00d64000-00d65000 rwxp 00009000 08:02 6291496 /lib/libnss_files-2.5.so 00dbf000-00dd2000 r-xp 00000000 08:02 6291504 /lib/libpthread-2.5.so 00dd2000-00dd3000 r-xp 00012000 08:02 6291504 /lib/libpthread-2.5.so 00dd3000-00dd4000 rwxp 00013000 08:02 6291504 /lib/libpthread-2.5.so 00dd4000-00dd6000 rwxp 00dd4000 00:00 0 00e6d000-00e8d000 r-xp 00000000 08:02 9080245 /usr/lib/freeradius/libfreeradius-radius-2.1.7.so 00e8d000-00e8e000 rwxp 00020000 08:02 9080245 /usr/lib/freeradius/libfreeradius-radius-2.1.7.so 00e8e000-00e8f000 rwxp 00e8e000 00:00 0 00eb3000-00ef6000 r-xp 00000000 08:02 6291673 /lib/libssl.so.0.9.8e 00ef6000-00efa000 rwxp 00042000 08:02 6291673 /lib/libssl.so.0.9.8e 00f94000-00f96000 r-xp 00000000 08:02 6291658 /lib/libcom_err.so.2.1 00f96000-00f97000 rwxp 00001000 08:02 6291658 /lib/libcom_err.so.2.1 08048000-08085000 r-xp 00000000 08:02 8988421 /usr/sbin/radiusd 08085000-08087000 rw-p 0003d000 08:02 8988421 /usr/sbin/radiusd 08087000-08088000 rw-p 08087000 00:00 0 0978e000-0a07d000 rw-p 0978e000 00:00 0 [heap] b19fb000-b19fc000 ---p b19fb000 00:00 0 b19fc000-b23fc000 rw-p b19fc000 00:00 0 b23fc000-b23fd000 ---p b23fc000 00:00 0 b23fd000-b2dfd000 rw-p b23fd000 00:00 0 b2dfd000-b2dfe000 ---p b2dfd000 00:00 0 b2dfe000-b37fe000 rw-p b2dfe000 00:00 0 b37fe000-b37ff000 ---p b37fe000 00:00 0 b37ff000-b41ff000 rw-p b37ff000 00:00 0 b41ff000-b4200000 ---p b41ff000 00:00 0 b4200000-b4c22000 rw-p b4200000 00:00 0 b4c22000-b4d00000 ---p b4c22000 00:00 0 b4dd9000-b4dda000 ---p b4dd9000 00:00 0 b4dda000-b57da000 rw-p b4dda000 00:00 0 b57da000-b57db000 ---p b57da000 00:00 0 b57db000-b61db000 rw-p b57db000 00:00 0 b61db000-b61dc000 ---p b61db000 00:00 0 b61dc000-b6bdc000 rw-p b61dc000 00:00 0 b6bdc000-b6bdd000 ---p b6bdc000 00:00 0 b6bdd000-b75dd000 rw-p b6bdd000 00:00 0 b75dd000-b75de000 ---p b75dd000 00:00 0 b75de000-b7fe3000 rw-p b75de000 00:00 0 b7fe7000-b7fe8000 rw-p b7fe7000 00:00 0 bf842000-bf858000 rw-p bffe9000 00:00 0 [stack] Aborted
Also in my postgresql log i see the following when radiusd dies
<2009-10-23 11:01:40.167 BST> LOG: SSL error: wrong version number <2009-10-23 11:01:40.167 BST> LOG: could not receive data from client: Connection reset by peer <2009-10-23 11:01:40.167 BST> LOG: unexpected EOF on client connection <2009-10-23 11:01:40.169 BST> LOG: could not receive data from client: Connection reset by peer <2009-10-23 11:01:40.169 BST> LOG: could not receive data from client: Connection reset by peer <2009-10-23 11:01:40.169 BST> LOG: unexpected EOF on client connection <2009-10-23 11:01:40.169 BST> LOG: unexpected EOF on client connection <2009-10-23 11:01:40.170 BST> LOG: could not receive data from client: Connection reset by peer <2009-10-23 11:01:40.170 BST> LOG: could not receive data from client: Connection reset by peer <2009-10-23 11:01:40.170 BST> LOG: unexpected EOF on client connection <2009-10-23 11:01:40.170 BST> LOG: unexpected EOF on client connection <2009-10-23 11:01:40.175 BST> LOG: could not receive data from client: Connection reset by peer <2009-10-23 11:01:40.175 BST> LOG: unexpected EOF on client connection <2009-10-23 11:01:40.175 BST> LOG: could not receive data from client: Connection reset by peer <2009-10-23 11:01:40.175 BST> LOG: unexpected EOF on client connection <2009-10-23 11:01:40.176 BST> LOG: could not receive data from client: Connection reset by peer <2009-10-23 11:01:40.176 BST> LOG: unexpected EOF on client connection <2009-10-23 11:01:40.176 BST> LOG: could not receive data from client: Connection reset by peer <2009-10-23 11:01:40.176 BST> LOG: unexpected EOF on client connection <2009-10-23 11:01:40.175 BST> LOG: could not receive data from client: Connection reset by peer <2009-10-23 11:01:40.177 BST> LOG: unexpected EOF on client connection <2009-10-23 11:01:40.177 BST> LOG: could not receive data from client: Connection reset by peer <2009-10-23 11:01:40.177 BST> LOG: unexpected EOF on client connection <2009-10-23 11:01:40.178 BST> LOG: could not receive data from client: Connection reset by peer <2009-10-23 11:01:40.178 BST> LOG: unexpected EOF on client connection
The message regarding SSL seems to alternate between the follwoing:
LOG: SSL error: wrong version number LOG: could not accept SSL connection: EOF detected LOG: SSL error: decryption failed or bad record mac LOG: SSL error: block cipher pad is wrong
In my radius.log i've noticed a couple of times there are some postgresql errors
Fri Oct 23 11:18:08 2009 : Info: rlm_sql (sql): Driver rlm_sql_postgresql (module rlm_sql_postgresql) loaded and linked Fri Oct 23 11:18:08 2009 : Info: rlm_sql (sql): Attempting to connect to postgres@localhost:/gapdb Fri Oct 23 11:18:08 2009 : Info: Loaded virtual server <default> Fri Oct 23 11:18:08 2009 : Info: Ready to process requests. Fri Oct 23 11:18:16 2009 : Error: [sql] stop packet with zero session length. [user 'JoePublic7', nas '172.20.200.226'] Fri Oct 23 11:18:16 2009 : Error: [sql] stop packet with zero session length. [user 'admin', nas '172.20.200.226'] Fri Oct 23 11:18:16 2009 : Error: [sql] stop packet with zero session length. [user 'admin', nas '172.20.200.226'] Fri Oct 23 11:18:16 2009 : Error: [sql] stop packet with zero session length. [user 'admin', nas '172.20.200.226'] Fri Oct 23 11:18:16 2009 : Error: [sql] stop packet with zero session length. [user 'admin', nas '172.20.200.226'] Fri Oct 23 11:18:16 2009 : Error: [sql] stop packet with zero session length. [user 'admin', nas '172.20.200.226'] Fri Oct 23 11:18:16 2009 : Error: rlm_sql_postgresql: PostgreSQL Query failed Error: Fri Oct 23 11:18:16 2009 : Error: rlm_sql_postgresql: Socket not connected Fri Oct 23 11:18:16 2009 : Error: [sql] stop packet with zero session length. [user 'admin', nas '172.20.200.226'] Fri Oct 23 11:18:16 2009 : Error: [sql] stop packet with zero session length. [user 'admin', nas '172.20.200.226'] Fri Oct 23 11:18:16 2009 : Error: [sql] stop packet with zero session length. [user 'admin', nas '172.20.200.226']
Fri Oct 23 11:19:02 2009 : Info: rlm_sql (sql): Driver rlm_sql_postgresql (module rlm_sql_postgresql) loaded and linked Fri Oct 23 11:19:02 2009 : Info: rlm_sql (sql): Attempting to connect to postgres@localhost:/gapdb Fri Oct 23 11:19:02 2009 : Info: Loaded virtual server <default> Fri Oct 23 11:19:02 2009 : Info: Ready to process requests. Fri Oct 23 11:19:05 2009 : Error: [sql] stop packet with zero session length. [user 'JoePublic7', nas '172.20.200.226'] Fri Oct 23 11:19:05 2009 : Error: [sql] stop packet with zero session length. [user 'admin', nas '172.20.200.226'] Fri Oct 23 11:19:05 2009 : Error: [sql] stop packet with zero session length. [user 'admin', nas '172.20.200.226'] Fri Oct 23 11:19:05 2009 : Error: [sql] stop packet with zero session length. [user 'admin', nas '172.20.200.226'] Fri Oct 23 11:19:05 2009 : Error: [sql] stop packet with zero session length. [user 'admin', nas '172.20.200.226'] Fri Oct 23 11:19:05 2009 : Error: [sql] stop packet with zero session length. [user 'admin', nas '172.20.200.226'] Fri Oct 23 11:19:05 2009 : Error: [sql] stop packet with zero session length. [user 'admin', nas '172.20.200.226'] Fri Oct 23 11:19:05 2009 : Error: [sql] stop packet with zero session length. [user 'admin', nas '172.20.200.226'] Fri Oct 23 11:19:05 2009 : Error: [sql] stop packet with zero session length. [user 'admin', nas '172.20.200.226'] Fri Oct 23 11:19:05 2009 : Error: [sql] stop packet with zero session length. [user '001f3b887d19', nas '172.20.200.226'] Fri Oct 23 11:19:05 2009 : Error: [sql] stop packet with zero session length. [user '001f3b887d19', nas '172.20.200.226'] Fri Oct 23 11:19:05 2009 : Error: [sql] stop packet with zero session length. [user 'admin', nas '172.20.200.226'] Fri Oct 23 11:19:05 2009 : Error: [sql] stop packet with zero session length. [user 'admin', nas '172.20.200.226'] Fri Oct 23 11:19:05 2009 : Error: [sql] stop packet with zero session length. [user 'admin', nas '172.20.200.226'] Fri Oct 23 11:19:05 2009 : Error: [sql] stop packet with zero session length. [user 'admin', nas '172.20.200.226'] Fri Oct 23 11:19:05 2009 : Error: rlm_sql_postgresql: PostgreSQL Query failed Error: SSL SYSCALL error: Resource temporarily unavailable
I've also setup a sql_log module to capture the sql queries being performed and later ran that sql succesfully with the command:
# psql -h 127.0.0.1 -U postgres gapdb < /var/log/radius/radacct/sql-relay
Again thank you for the help, hope this helps.
Cheers,
Duarte
On 22/10/2009 18:17, "Alan DeKok" <aland@deployingradius.com> wrote:
Duarte Fonseca wrote:
I've got a freeRadius (v2.1.7) install running on CentOs using postgresql to store accounting data and have noticed that occasionally freeRadius seems to die unexpectedly.
See doc/bugs. You can run the server in foreground mode (radiusd -f), too.
If it dies after a few packets, the problem should be pretty simple to find && fix.
Alan DeKok. - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
Thank you Alan, Cheers, Duarte 2009/11/6 Alan DeKok <aland@deployingradius.com>:
Duarte Fonseca wrote:
Hi list,
Just checking if anyone has any more suggestions on how I should proceed with this.
A fix is in the "stable" branch of git.
Alan DeKok. - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
Hi Alan, If you could point out which specific commit(s) address this issue I would be very grateful. Thank you, Duarte 2009/11/6 Alan DeKok <aland@deployingradius.com>:
Duarte Fonseca wrote:
Hi list,
Just checking if anyone has any more suggestions on how I should proceed with this.
A fix is in the "stable" branch of git.
Alan DeKok. - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
Duarte Fonseca wrote:
Hi Alan,
If you could point out which specific commit(s) address this issue I would be very grateful.
$ git log src/modules/rlm_sql/drivers/rlm_sql_postgresql ... 45877bf44b02d418b6fb263a39e5de07ced58b6e Alan DeKok.
Duarte Fonseca <fonseca.duarte@gmail.com> wrote:
If you could point out which specific commit(s) address this issue I would be very grateful.
One day we will persaude Alan to put something more verbose in the git commit logs :) Until then: ---- git log -p -n1 src/modules/rlm_sql/drivers/rlm_sql_postgresql/ ---- It was the recent commit 45877bf44b02d418b6fb263a39e5de07ced58b6e. Cheers -- Alexander Clouter .sigmonster says: Would you care to drift aimlessly in my direction?
Thanks Alan and Alex, I thought it was that one, just wanted to make sure as I gave it a quick test and it seems the problem is still there. I'm doing some more tests to make sure it's not me doing something silly, I'll be in touch if I keep having problems (hopefully with gdb and valgrind output). Thank you, Duarte 2009/11/12 Alexander Clouter <alex@digriz.org.uk>:
Duarte Fonseca <fonseca.duarte@gmail.com> wrote:
If you could point out which specific commit(s) address this issue I would be very grateful.
One day we will persaude Alan to put something more verbose in the git commit logs :)
Until then: ---- git log -p -n1 src/modules/rlm_sql/drivers/rlm_sql_postgresql/ ----
It was the recent commit 45877bf44b02d418b6fb263a39e5de07ced58b6e.
Cheers
-- Alexander Clouter .sigmonster says: Would you care to drift aimlessly in my direction?
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
Hi again, So the problem seems to still be present, this is how I'm testing, please let me know if I'm doing something wrong. I got the redhat SRPM from http://people.redhat.com/jdennis/freeradius-rhel-centos/src/freeradius2-2.1.... Applied the change to the source file and built the binary rpm, installed it and re run my test several times, and it kept failing. I've rebuilt the rpm with --enable-developer and captured the following with gdb and valgrind. http://dl.dropbox.com/u/797051/radiusd/gdb-radiusd.log http://dl.dropbox.com/u/797051/radiusd/valgrind-radiusd.log I also tried replacing the full source with the latest from git(stable) but I failed to get it to build a rpm. Is there any other changes that I need to apply to the 2.1.7 source? Thank you, Duarte 2009/11/12 Duarte Fonseca <fonseca.duarte@gmail.com>:
Thanks Alan and Alex,
I thought it was that one, just wanted to make sure as I gave it a quick test and it seems the problem is still there.
I'm doing some more tests to make sure it's not me doing something silly, I'll be in touch if I keep having problems (hopefully with gdb and valgrind output).
Thank you,
Duarte
2009/11/12 Alexander Clouter <alex@digriz.org.uk>:
Duarte Fonseca <fonseca.duarte@gmail.com> wrote:
If you could point out which specific commit(s) address this issue I would be very grateful.
One day we will persaude Alan to put something more verbose in the git commit logs :)
Until then: ---- git log -p -n1 src/modules/rlm_sql/drivers/rlm_sql_postgresql/ ----
It was the recent commit 45877bf44b02d418b6fb263a39e5de07ced58b6e.
Cheers
-- Alexander Clouter .sigmonster says: Would you care to drift aimlessly in my direction?
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
On 11/12/2009 11:38 AM, Duarte Fonseca wrote:
Hi again,
So the problem seems to still be present, this is how I'm testing, please let me know if I'm doing something wrong.
I got the redhat SRPM from
http://people.redhat.com/jdennis/freeradius-rhel-centos/src/freeradius2-2.1....
Applied the change to the source file and built the binary rpm, installed it and re run my test several times, and it kept failing.
Let's be clear concerning the statement "Applied the change to the source file". You must add the patch to the spec file and then build the binary rpm, you can't just patch a source file. That's because rpmbuild unpacks the tar file, applies *only* the patches listed in the spec file, and then builds the result. If you don't modify the spec file to add the patch then the patch will never get applied. -- John Dennis <jdennis@redhat.com> Looking to carve out IT costs? www.redhat.com/carveoutcosts/
Hi John, The only change I did to the spec file was change the release (and later add the --enable-developer) What I did do was go to the SOURCES dir and unpack the freeradius-server archive, change the file in question, pack up freeradius-server replacing the original tar.bz2 archive. I did this assuming rpm build would build using whatever code is in that tar.bz2 file. Is this another case of assumption being the mother of all f*ckups? Thank you, Duarte 2009/11/12 John Dennis <jdennis@redhat.com>:
On 11/12/2009 11:38 AM, Duarte Fonseca wrote:
Hi again,
So the problem seems to still be present, this is how I'm testing, please let me know if I'm doing something wrong.
I got the redhat SRPM from
http://people.redhat.com/jdennis/freeradius-rhel-centos/src/freeradius2-2.1....
Applied the change to the source file and built the binary rpm, installed it and re run my test several times, and it kept failing.
Let's be clear concerning the statement "Applied the change to the source file". You must add the patch to the spec file and then build the binary rpm, you can't just patch a source file. That's because rpmbuild unpacks the tar file, applies *only* the patches listed in the spec file, and then builds the result. If you don't modify the spec file to add the patch then the patch will never get applied.
-- John Dennis <jdennis@redhat.com>
Looking to carve out IT costs? www.redhat.com/carveoutcosts/ - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
On 11/12/2009 12:28 PM, Duarte Fonseca wrote:
Hi John,
The only change I did to the spec file was change the release (and later add the --enable-developer)
What I did do was go to the SOURCES dir and unpack the freeradius-server archive, change the file in question, pack up freeradius-server replacing the original tar.bz2 archive.
I did this assuming rpm build would build using whatever code is in that tar.bz2 file. Is this another case of assumption being the mother of all f*ckups?
You can do it this way, but it's like trying to use a hammer to drive a screw :-) The whole rationale of RPM packaging is based around applying patches to upstream sources, which in this instance is exactly what you're doing. -- John Dennis <jdennis@redhat.com> Looking to carve out IT costs? www.redhat.com/carveoutcosts/
Hi John, As long as the hammer does the job. At this stage although I'm aware that RPM packaging is much more powerful my lack of knowledge about it doesn't allow for a more sensible approach. Hopefully this will change time ;) thanks, Duarte 2009/11/12 John Dennis <jdennis@redhat.com>:
On 11/12/2009 12:28 PM, Duarte Fonseca wrote:
Hi John,
The only change I did to the spec file was change the release (and later add the --enable-developer)
What I did do was go to the SOURCES dir and unpack the freeradius-server archive, change the file in question, pack up freeradius-server replacing the original tar.bz2 archive.
I did this assuming rpm build would build using whatever code is in that tar.bz2 file. Is this another case of assumption being the mother of all f*ckups?
You can do it this way, but it's like trying to use a hammer to drive a screw :-) The whole rationale of RPM packaging is based around applying patches to upstream sources, which in this instance is exactly what you're doing. -- John Dennis <jdennis@redhat.com>
Looking to carve out IT costs? www.redhat.com/carveoutcosts/ - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
Duarte Fonseca <fonseca.duarte@gmail.com> wrote:
So the problem seems to still be present, this is how I'm testing, please let me know if I'm doing something wrong.
I got the redhat SRPM from
http://people.redhat.com/jdennis/freeradius-rhel-centos/src/freeradius2-2.1....
Applied the change to the source file and built the binary rpm, installed it and re run my test several times, and it kept failing.
---- git clone http://git.freeradius.org/freeradius-server.git cd freeradius-server git checkout origin/stable git checkout -b mybranch ---- That will give you what is to become 2.1.8 and the patches in there are considered stable. If you want to go with 2.1.7 then: ---- git checkout release_2_1_7 git checkout -b mybranch git cherry-pick 45877bf44b02d418b6fb263a39e5de07ced58b6e ---- You should also compile the whole thing with optimisations turned off and debugging symbols in there; you are not doing the former so it might make it more difficult to work out what is wrong: ---- CFLAGS='-O0 -g' ./configure ---- You Redhat folk might have a Redhat Way(tm) to do the above though?
I've rebuilt the rpm with --enable-developer and captured the following with gdb and valgrind.
http://dl.dropbox.com/u/797051/radiusd/gdb-radiusd.log http://dl.dropbox.com/u/797051/radiusd/valgrind-radiusd.log
To my untrained eye it looks like the bug in in libpq, unless libpq is being handed a mangled pointer by FreeRADIUS. Looks rather similar to: http://archives.postgresql.org/pgadmin-hackers/2009-01/msg00079.php
I also tried replacing the full source with the latest from git(stable) but I failed to get it to build a rpm.
Ah....well...I can give you the Debian destructions :) Cheers -- Alexander Clouter .sigmonster says: Goodbye, cool world.
Hi Alex, Again thanks for the help. 2009/11/12 Alexander Clouter <alex@digriz.org.uk>:
You should also compile the whole thing with optimisations turned off and debugging symbols in there; you are not doing the former so it might make it more difficult to work out what is wrong: ---- CFLAGS='-O0 -g' ./configure ----
Here is the gdb output and valgrind with these flags set. http://dl.dropbox.com/u/797051/radiusd/gdb-radiusd-2.log http://dl.dropbox.com/u/797051/radiusd/valgrind-radiusd-2.log Thank you, Duarte
Duarte Fonseca <fonseca.duarte@gmail.com> wrote:
2009/11/12 Alexander Clouter <alex@digriz.org.uk>:
You should also compile the whole thing with optimisations turned off and debugging symbols in there; you are not doing the former so it might make it more difficult to work out what is wrong: ---- CFLAGS='-O0 -g' ./configure ----
Here is the gdb output and valgrind with these flags set.
http://dl.dropbox.com/u/797051/radiusd/gdb-radiusd-2.log http://dl.dropbox.com/u/797051/radiusd/valgrind-radiusd-2.log
This is a different implosion this time round to your last one. Looks like Alan's SQL patch simply postponed the SIGSEGV to a different part of the code. Not sure what should be done, but it looks like errorcode also needs to be changed (probably set to NULL explicitly or something). Alternatively it might be that the error code table in sql_postgresql.h needs updating? No real idea here, Alan? I only was able to trigger this bug once, and that was during a spanning-tree going crazy (scheduled test of a reboot of one of our core routers) when FreeRADIUS would have been unable to talk to the SQL server. Although FreeRADIUS should not be dying, it does make me wonder why you can reproduce this problem so regularly :) Cheers -- Alexander Clouter .sigmonster says: Feminists just want the human race to be a tie.
Alexander Clouter wrote:
This is a different implosion this time round to your last one. Looks like Alan's SQL patch simply postponed the SIGSEGV to a different part of the code. Not sure what should be done, but it looks like errorcode also needs to be changed (probably set to NULL explicitly or something). Alternatively it might be that the error code table in sql_postgresql.h needs updating? No real idea here, Alan?
I'd suggest changing sql_query() function in sql_postgresql.c to: ... if (!errormsg) return -1; ... instead of the current block of code { errormsg = "FATAL ERROR" }
Although FreeRADIUS should not be dying, it does make me wonder why you can reproduce this problem so regularly :)
It's not FreeRADIUS... it's the PostgreSQL libraries. They are supposed to return an error code and message... they don't. Then, when they don't, they go crazy. We've got to work around bugs in libraries we use. <sigh> Alan DeKok.
Alan DeKok <aland@deployingradius.com> wrote:
This is a different implosion this time round to your last one. Looks like Alan's SQL patch simply postponed the SIGSEGV to a different part of the code. Not sure what should be done, but it looks like errorcode also needs to be changed (probably set to NULL explicitly or something). Alternatively it might be that the error code table in sql_postgresql.h needs updating? No real idea here, Alan?
I'd suggest changing sql_query() function in sql_postgresql.c to:
... if (!errormsg) return -1; ...
instead of the current block of code { errormsg = "FATAL ERROR" }
As Duarte is so able to reproduce this bug I guess this is over to him? Cheers -- Alexander Clouter .sigmonster says: Cure the disease and kill the patient. -- Francis Bacon
Hi,
I'd suggest changing sql_query() function in sql_postgresql.c to:
... if (!errormsg) return -1; ...
instead of the current block of code { errormsg = "FATAL ERROR" }
Well I tried this change, you can see the gdb output at: http://dl.dropbox.com/u/797051/radiusd/gdb-radiusd-3.log Hope it helps.
As Duarte is so able to reproduce this bug I guess this is over to him?
As for reproducing this, it's pretty straightforward if I follow the steps I outlined in my first e-mail, as anyone else reproduced this successfully? cheers, Duarte
participants (4)
-
Alan DeKok -
Alexander Clouter -
Duarte Fonseca -
John Dennis